MethodCallSpy – technical notes for curious

Two Types of Weaving in AOP

Build Time Weaving is more of a style of a regular programming. Aspects are typically as an integral part of target application. It is used to achieve a greater Separation of Concerns, where it cannot be easily reached by ordinary design patterns, to keep code simple and readable. Typical usage – unobtrusive logging, declarative transaction management, transparent caching. These things may “pollute” main code from a design point of view or compromise speed when even a few surplus condition matter. You can easily remove all logging commands as a mater of changing a single build configuration option, without a single change in source code.

AspectJ distinguishes Compile-time weaving (source code level) and Post-compile weaving (binary class weving). I dared to put them in one category for purpose of this article.

The Load Time Weaving (LTW) is rather a technique for ad hoc modification of unsuspecting target application in runtime. You “hack in” to the target application. Such Aspects are developed separately from target code. Often without having access to the original source code. It is used only for specific tasks, like method tracing, performance monitoring.

Imagine this situation. You have build application, a JAR or WAR, it passed whole formal releasing process, not a trivial thing in big corporations, it was successfully deployed. But then you suspect an issue. Unfortunately, none put any logging to the suspected part of the application. Time is crucial, rebuild is not an option. LTW is to rescue. Write simple advice, targeted to specific package or class, log internal states. Still, the server needs to be restarted, start up parameters added to include the aspect related, but still better then full rebuild and redeployment.

Or this scenario. You need to trace used classes do do some serious cleaning. Your application is still in development, in environment you control. You could rebuild it using regular build time weaver with ajc compiler. However, lets assume it is a legacy application, mature, with complex build, chain of build tools, mixture of JVM languages, Java and Groovy, not necessary a Maven build, figuring out where to plug ajc compiler and having the confidence all intended classes were really advised, it may be tricky business. Time consuming. Much simpler and safer is to use LTW.

For more read here.

Code based style versus annotation based style

AspectJ supports two styles, the original code based, and from version 1.5 also annotation based style. TraceAgent code uses annotation based style. You can clearly see @Pointcut , @After, @Before, @Around, @Aspect from package org.aspectj.lang.annotation. After in source code of TraceAllAgent class.

Benefit is, you don't need any special compiler or IDE plugin. Just core Java and basic Eclipse JDT. Disadvantage is, it does not syntactically checks the pointcut definitions, there is no indication which classes are affected by the aspects. Everything is evaluated only in runtime. AspectJ has excellent plugin – AJDT or Eclipse plugin for AspectJ. It is actively developed, currently in version 2.2.1. See video demonstrations what it can do. If you plan to deal with aspects more intensively, it would pay off to invest time and effort and set up you IDE and tool chain accordingly and use aspect classes (*.aj files). For our all method tracing agent, a one off tool, it is no brainer to pick annotation based rules definition.

The use of the @AspectJ annotations means that application can be compiled by a regular Java 5 compiler, and subsequently woven by the AspectJ weaver (for example, as an additional build stage, or as late as class load-time).

Unfortunately annotation based style is much less documented. Most available examples on internet use code based style. The official developers guide - The AspectJ Programming Guide (link) – barely mentions annotation style. The best (if not only) documentation to @AspectJ annotations are in the older guide The AspectJ 5 Development Kit Developer's Notebook, see chapter chapter 9 there:
http://www.eclipse.org/aspectj/doc/released/adk15notebook/ataspectj-pcadvice.html

This "developers notebook" is still far more complete documentation then Programming Guide. As a preffered source of information is suggested even by AspectJ authorities.

Code based style versus annotation based style – comparison

Code based style. Note the aspect keyword instead usuall class.

public aspect Foo {
      pointcut listOperation() : execute(* java.util.List.*(..));
      pointcut anyUtilityCall() : execute(* my.home.util..*(..));
      before() : listOperation() {
         System.out.println(...);
      }
      after() : anyUtilityCall() {
         System.out.println(...);
      }
}

Equivalent in annotation based style, using @AspectJ annotations.

@Aspect
public class Foo {
      @Pointcut("execute(* java.util.List.*(..))")
      void listOperation() {}

      @Pointcut("execute(* my.home.util..*(..))")
      void anyUtilityCall() {}


     @Before("listOperation()")
     public void logAllMethodsOnAList() {
       // advice method name is can be anything
       System.out.println(...);
     }
     @After("anyUtilityCall()")
     public void logUtilityMethods() {
       System.out.println(...);
     }
}

In most situations you can simplify this even more:

@Aspect
public class Foo {
     @Before(pointcut = "execute(* java.util.List.*(..))")
     public void logAllMethodsOnAList() {
       // advice method name is can be anything
       System.out.println(...);
     }
     @After(pointcut = "execute(* my.home.util..*(..))")
     public void logUtilityMethods() {
       System.out.println(...);
     }
}

Advice methods - those annotated with @Before, @After etc. - can have arguments. You can handle (selected) arguments in this way, as a proper named arguments, or some other runtime information, like reference to calling instance.

Or you can add JoinPoint as an advice argument as in TraceAllAgent class.

@Before("allMethodsAllClasses()")
public void beforeTracedMethods(JoinPoint joinPoint) {
     String className = joinPoint.getStaticPart()
          .getSignature().getDeclaringTypeName();
     . . .
}

Conditional advice execution

Point cut method is usually empty, unless you use if() pointcut expression:

@Pointcut("call(* *.processEvent(JComponent)) && args(eventSource) && if()")
public static boolean someCallWithIfTest(Widget w) {
     return eventSource instanceof JButton;
}

Note that return value is now boolean and not void. Call the advice only when only when condition is satisfied, that is when processMedhod parameter is JButton and only then.

Maven dependencies

<dependency>

     <groupId>aspectj</groupId>

     <artifactId>aspectjweaver</artifactId>

     <version>1.5.4</version>

</dependency>

<dependency>

     <groupId>aspectj</groupId>

     <artifactId>aspectjrt</artifactId>

     <version>1.5.4</version>

</dependency>

<dependency>

     <groupId>aspectj</groupId>

     <artifactId>aspectjtools</artifactId>

     <version>1.5.4</version>

</dependency>

Much newer version of AspectJ is available in the time of writing – AspectJ 1.7.1.
However in main Maven repository was 1.5.4 still the latest so I stuck with it. No issues.

Interesting links

AspectJ homepage - http://www.eclipse.org/aspectj/

http://www.eclipse.org/aspectj/doc/released/progguide/index.html - The AspectJ Programming Guide

http://www.eclipse.org/aspectj/doc/released/adk15notebook/ - The AspectJ 5 Development Kit Developer's Notebook

http://www.eclipse.org/aspectj/doc/next/devguide/ltw.html - Load-Time Weaving chapter in Developers Guide. Also explains Compile-time and Post-compile weaving.

AJDT or Eclipse plugin for AspectJ

http://www.eclipse.org/aspectj/doc/next/adk15notebook/annotations-pointcuts-and-advice.html - Join Point Matching based on Annotations. Do NOT confuse this with annotation based style. This chapter is about intercepting only methods with certain annotation and similar rules.

http://www.eclipse.org/aspectj/doc/next/progguide/semantics-pointcuts.html – list of all (?) possible pointcut definitions with examples. Note, everything is in code based style. But you should be now able co convert them to annotation based style. See chapter above.

http://www.eclipse.org/aspectj/doc/released/faq.php#q:comparecallandexecution
What is the difference between call and execution join points?
Summary: Since AspectJ 1.1 you should use the execute() pointcut designator unless you have a good reason to use call().

http://www.eclipse.org/aspectj/doc/released/faq.php#q:codeversusannotationstyles
Should I use code- or annotation-style aspects?

http://www.eclipse.org/aspectj/doc/next/progguide/starting-aspectj.html#inter-type-declarations – another interesting feature of AspectJ. You can add methods, fields and even modify hierarchy using these inter type declarations. However, it looks like it can be used only with compile time weaving, not LTW.

Appendix – code to locate AspectJ jar on classpath

To detect full path to AspectJ agent library, something suitable for tests, not tied to any file system layout, I wrote this utility method:

public static String getAspectjWeaverJarFullPath() {

     ClassLoader loader = SampleMultithreadAppTest.class.getClassLoader();

     String aspectjTypicalClass = "org/aspectj/weaver/ltw/LTWeaver.class";

     String aspectjUrl = loader.getResource(aspectjTypicalClass)

          .toExternalForm();

     return aspectjUrl.substring(aspectjUrl.indexOf('/') + 1,

          aspectjUrl.indexOf(".jar!") + 4);

}

The method looks for a prominent AspectJ class, containing pre-main method, the entry point of any Java Agent. Classes can be seen as files in a directory, so ClassLoader is able to find them by getResource(), don't forget to use “/”instead “.” and add file suffix of “.class”. Method toExternalForm then return something like:
jar:file:/home/dev/maven_repo/org/aspectj/aspectjweaver/1.5.4/aspectjweaver-1.5.4.jar!/org/aspectj/weaver/ltw/LTWeaver.class. With some careful text stripping we can get path to AspectJ weaver jar. AspectJ weaver jar has to be on the classpath, we can take it as granted here, see the general requirements in the previous article.

This approach is better alternative to search through classpath string. It can deal with non-standard AspectJ names, like having version included in name or not, or non-standard assembly, like bulk all-in-one JAR. Until LTWeaver class in package org.aspectj.weaver.ltw, it will work.

MethodCallSpy – building advanced socket listening tracing tool

The MethodCallSpy is sophisticated, multi threaded application with simple socket base IPC, listening to remote commands, gathering and aggregating tracing data.

Links to source codes:
https://bitbucket.org/espinosa/methodcallspy

MethodCallSpy is still not an enterprise grade tracing tool, not a YourKit replacement, but a specialized purpose tool and perhaps a base for similar projects of my dear readers. Tool similar to this we did use in real world scenario, in a commercial project for purpose of finding all classes still in use for specific tasks. It uses AspectJ.

MethodCallSpy

• aggregates tracing data and stores them to file
• listens on socket for commands
• it can suspend and resume application, in similar fashion as debugger does
• tracing can be switched on and off for readings to be made only when relevant functionality is launched

Besides AOP it is an example of:

• multi threaded application
• socket server and client
• simple text based IPC (Inter Process Communication) for delivering commands to the agent
• complex integration test with forking another JVM, capturing and filtering streams, tested application forced timeout (for misbehaved not blocking whole Continuous Integration server)
• good software design, notably Separation of Concerns. Aspect related code is used a bootstrapping class for simple context. Context instantiates other services like socket listening server, command processor or results writing service.
• Advanced testing. Custom context can be replaced with testing one for advanced integration test scenarios.

Motivation

Previously introduced MethodCallSpy0 has several shortcomings. It runs with application all the time, tracing everything along the way. Take a Spring based application, when it context is created, most beans are called in some way, even those not really used later. Such statistic would be unusable for “still needed” list of classes. Imagine, we need to list of used classes only for a specific functionality triggered by a user or event.

We need something we can control remotely. Stop tracing through initialisation phase, start tracing and gathering statistics when it counts. We have to add some IPC mechanism to make it controllable. To implement IPC I choose the simplest solution at hand – socket server.

We also need to persist (flush) readings to file. It can be done on request, by issuing specific command, or automatically when application ends.

Some scenarios may require to temporarily suspend application so I add this functionality too.

How to run MethodCallSpy

How to run with your application from command line:
java -cp <classpath> -javaagent:<full path to AspectJ library> -DtraceAgentOutputDir=<absolute path> targetAppClass

The classpath must include target application JAR and its libraries indeed, besides that AspectJ libraries, agent classes like TraceAllAgent.class, and AOP configuration file – aop.xml. The configuration file must be inside META-INF directory, top level directory. Ideally agent classes, like TraceAllAgent.class, should be ideally packed with the aop.xml in one jar.

All readings are stored in specified directory. File names with the readings are timestamped, so readings can be stored repeatedly. From historic reasons, there are two files created with every flush. One contains only classes – the c-file, the other classes and methods – the cm-file. Files names are combination of timestamp and suffix “.c.traceagent.log” or “.cm.traceagent.log”.

Every class/method is traced (registered) only once and content is alphabetically sorted.

The content of the class and method may look like:
my.home.sampleapplication.SampleSimpleApp#main(..)
my.home.sampleapplication.SampleSimpleApp#somePublicMethod(..)

One configuration step is required in aop.xml. Define what packages from the target application should be traced. Change the default value to something meaningful for you application. The double dot is crucial, it recursively include also all sub packages. Or use all inclusive <include within="*" /> but use it with care.

Target application is suspended by default. It waits for user interaction, like starting or not tracing. User has to issue resume command for application to resume.

Socket communication

Tracing agent listens port 4444 by default, it can be changed with traceAgentPort environment option. Example: -DtraceAgentPort=8008

To issues command user needs some tool enabling writing and reading from a socket on specified port. In Unix environments it is simple, standard shell echo can be redirected to a socket device. Example:
$ echo "start" > /dev/tcp/127.0.0.1/4444

A special custom socket client, very simple, practically one method only, is used in tests.

Command list

• ping – check if MethodCallSpy is active and listening, just print OK
• start – activate tracing
• stop – deactivate (stops) tracing
• print – print trace snapshot to file
• stat – shows if tracing is active and target application resumed or suspended
• resume – resume target application. Reminder that target application is suspended by default. User has time to set up tracing even for very short lived applications.
• suspend – suspend target application

See CommandProcessor class for details. Commands are case sensitive. Simple commands, none of them require any additional parameters.

Session example

$ java -cp …. -javaagent:/usr/javalibs/aspectj/aspectjweaver.jar \
-DtraceAgentOutputDir=/home/foo/tmp/trace-agent-readings \
-DtraceAgentPort=4445 \
my.home.SampleApp1
$ echo "start" > /dev/tcp/127.0.0.1/4444
$ echo "resume" > /dev/tcp/127.0.0.1/4444
$ echo "stop" > /dev/tcp/127.0.0.1/4444
$ echo "print" > /dev/tcp/127.0.0.1/4444

How to configure tracing for Tomcat hosted application

Configure container based application is more challenging then standalone applications. The challenge usually takes form of figuring out how to add extra environment properties and amend classpath. With Tomcat you need:

1) Find <path_to>/tomcat7/conf/catalina.properties

2) Locate property common.loader,

3) append tracing agent jar and AspectJ libraries, separated by comma. Instead trace agent jar, an “expanded archive”, root directory with compiled classes can be used

Example:
common.loader=...,/home/foo/workspace/project/bin,/usr/javalibs/aspectj/*.jar

4) in shell start Tomcat as

export CATALINA_OPTS="-javaagent:<path_to>/aspectjweaver.jar \ -DtraceAgentOutputDir=<output_directory_for_trace_files> \
-DtraceAgentPort=4444 \
./catalina.sh run

Logging

By default, tracing agent does not print anything to standard output. It only logs using standard Java logging framework. Set -Djava.util.logging.ConsoleHandler.level=FINE to see agent log messages in console.

Tests

Usage and abilities is well demonstrated on included tests. One can see what commands can be issues. Integration tests starting another JVM to get instrumentation and socket end to end communication properly tested. There are Tests focused on nested classes tracing.

Test contains simple socket client, see TestUtils.sendCommand() for sending a text command and receiving reply from the tracing agent.

Test2TraceMultithreadedApp – test specifically to ensure handling of multi-threaded applications, where threads outlive main thread and correctly trace all threads.

More complex multi threaded testing scenarios are complicated by lack of simple cross JVM instance lock and other classes from concurrency package. Something like CountDownLatch with remote interface would be very useful. Such implementation is however out of scope for a once off tracing tool.

To be continued..

In the next article we look at some more technical details

MethodCallSpy – building own method tracing Java Agent with AspectJ

I have just released – MethodCallSpy – a simple JVM method tracing agent. This article and the released source code is to help anyone in how to modify existing Java program behaviour in runtime. Let's use method tracing as a good example of practical application.

Its not only a good demonstration of what AOP can do for you, but this tool was really used in production. We used tool similar to MethodCallSpy to trace classes that are still in practical use in a legacy applications, to detect and eventually remove unused code to slash maintenance costs.

There are better tools do exist. Professional, commercial ones, notably YourKit. But it is an overkill for a once off usage, for task I described above. I could not quickly find any suitable free tool so I wrote my own.

MethodCallSpy goes in two flavours. The first is mainly for demonstration purposes, an intermediate step in the development of more realistically usable tool. The second instalment is such tool. The MethodCallSpy0 may serve as a good base for your experiments with Aspect programming. It simply prints every traced method to console. The MethodCallSpy is sophisticated, multi threaded application with simple socket base IPC, listening to remote commands, gathering and aggregating tracing data.

Links to source codes:
https://bitbucket.org/espinosa/methodcallspy
https://bitbucket.org/espinosa/methodcallspy0

You can trace not only Java programs, but practically any JVM application, originally written in Groovy, Scala or JRuby. It does not guarantees the result will be usable in all scenarios. We have tested it on Groovy server based application, running on Tomcat, and it captured what we wanted.

MethodCallSpy0

Let's first look at the simpler variant. When MathodCallSpy0 runs with application as a Java agent it simply prints all methods and classes used to standard output. It is a Maven project, it takes care of all dependencies transparently. Run time modification of target application is done with AspectJ framework and its Load Time Weaver.

How to run and what is supposed to do is clear from the integration test – TraceAllAgentTest – but let's describe it also here.

How to run with your application:
java -cp <classpath> -javaagent:<full path to AspectJ library> targetAppClass

The classpath must include target application JAR and its libraries indeed, besides that AspectJ libraries, agent classes like TraceAllAgent.class, and AOP configuration file – aop.xml. The configuration file must be inside META-INF directory, top level directory. Ideally agent classes, like TraceAllAgent.class, should be ideally packed with the aop.xml in one jar.

But first of all, specify in aop.xml what packages to trace. What packages from the target application should be intercepted, or advised in AOP terminology. Change the <include within="my.home.sampleapplication..*" /> to something meaningful for you application. The double dot. This is crucial, it recursively include also all sub packages. Or use all inclusive <include within="*" /> but use it with care.

The intended output is trace print of all public methods and may look like:
>>> called class: my.home.sampleapplication.SampleApp method: main(..)
>>> called class: my.home.sampleapplication.SampleApp constructor
>>> called class: my.home.sampleapplication.SampleApp method: somePublicMethod(..)

All messages generated by the trace agent are simply prefixed with >>> just to distinguish agent output from general application output. There is a stream filtering utility in the test intended to capture just the agent output. See Utils.filterLinesStartingWith() method.

And that is all what MethodCallSpy0 can do for you. It starts with application, it ends with application. It traces all packages classes and methods from packages listed in aop.xml.

Tests

The behaviour of MethodCallSpy0 is well demonstrated in the integration tests. It is a proper end to end test with a sample application being advised in runtime, using a forked JVM process and LTW (Load Time Weaving). Modified behaviour tested is on redirected output from application, filtered and searched for tracing agent messages. For simplicity all trace agent output is prefixed with >>>.

Relevant parts:

ProcessBuilder pb = new ProcessBuilder(

  "java",

  "-cp", classpath,

  "-javaagent:"+aspectjWeaverJarFullPath,

SampleApp.class.getName());

pb.redirectErrorStream(true);

Process p = pb.start();

String result = Utils.dumpProcessOutputToString(p.getInputStream());

int exitValue = p.waitFor();

Assert.assertEquals(0, exitValue);

Assert.assertEquals("" +

  ">>> called class: my.home.sampleapplication.SampleApp method: main(..)\n" +

  ">>> called class: my.home.sampleapplication.SampleApp constructor",
  Utils.filterLinesStartingWith(">>>", result));

There should be no output from the test itself. The whole captured output however is reprinted at the end of the test to a logger. To see this run the test with system parameter -Djava.util.logging.ConsoleHandler.level=FINE. There may be some logging messages from AspectJ weaving process of interest.

The output is logged using plain Java logging framework – java.util.logging. It is very limited in its abilities compared to Log4j or Slf4j. But it perfectly matches needs for this test and does not require any external library.

What is Java Agent?

The runtime modification of target application is no hacking. Java from version 1.4 provides instrumentation service, package java.lang.instrument. It officially enables agents to modify any program running on JVM. Java Agents are (usually) small programs written (usually) in Java itself (or any JVM based language) to modify behaviour of another Java (Scala, Groovy) program.

Java Agent does not necessary has to do anything with AOP, Java Agent enables AOP's load time weaving to happen. Also, not all AOP systems use or even supports run time modification of target code.

MethodSpyCall, or TraceAllAgent class, is not, technically speaking, the Java Agent. AspectJ framework is the agent. It does all the byte code manipulation. MethodCallSpy is just a hosted.

Configuration file – aop.xml

The real Java Agent is the AspectJ library. The aop.xml configuration file is the connecting link between them. MethodCallSpy's TraceAllAgent class is defined here as Aspect. This class will be scanned for aspect defining annotations. Aspect class TraceAllAgent must be annotated with @Aspect.

The configuration file also restricts what packages to be changed in runtime to what aspect defines internally with its @Pointcut annotated methods. Only those packages defined here will be affected.

The aop.xml must be in the top level META-INF directory on the classpath. You have to explicitly specify what packages to trace. Or you can make it all inclusive, but use it with care, all core Java classes will be traced too, all eventual libraries.

Agent class (package) has to be part of the included classes! otherwise you get Stack Overflow in an infinite loop. It has to be excluded by cross-cutting definition in the code.

Inclusions are not recursive by default. To include sub packages use double dot and star notation. It is same with pointcut defining rules in Java code too.

What is AspectJ? Why AOP?

The runtime code modification is done through instrumentation and class byte code manipulation. Using it directly is tedious, challenging business, it requires great insight into most intimate parts of class structure. AspectJ shields users from this complexities, enabling developer to define modifications in more friendly AOP instruments – aspects, pointcuts and advices – defining what to do before, after or instead of a specified methods, or similar blocks of code. This is limiting, but usually fully satisfy common needs for runtime program modification like tracing, monitoring, debugging, performance measurement or test code coverage.

To be continued..

In the next article we look at the more advanced variant – MethodCallSpy – and some technical details.

The art of GWT logging

Basic option – GWT.log()

From the early times GWT provides one all purpose log method. GWT.log(“something something”). It is very basic, a static method requiring no special set up. List of benefits ends here.

Test of endurance is even to find the log. Nothing is printed to standard output. Nowhere to configure it. Numerous developers gave up here and resulted in all time favourite System.out.println().

The logs are displayed in Development Mode – an Eclipse view – in a form of bullet list! See the screenshot. If you click on it, you get the details like timestamp. It is easy to overlook. The is one nice feature compared to standard console – as-you-type filter. If you don't use Eclipse, or in older versions of the plugin, small helper Swing application showed them – GWT Shell.

What about web browsers? They do have various developer tools. Firefox has facility, called Web Console (Ctrl+Shift+K), it is to be found in main menu under Web Developer. However this console does not display GWT.log() messages. Similar functionality can be found in Chromium (Tools → JavaScript Console or Developer Tools). Same tool, same result, nothing is displayed from GWT.log(). Same with IE.

I don't have Firebug installed so I can tell if this plugin helps. Is it still considered the best product of its kind?

Also note, that log(), the very method calls, are automatically removed in Production Mode builds.

Proper GWT logging

So how we can see our logs? Conveniently in a web browser, in a console? We need to look for something more featured. Meet GWT Logger library.

GWT logging is based on standard Java Logging interfaces.

import java.util.logging.Logger;

In module configuration file (gwt.xml) needs to be set up:

<inherits name="com.google.gwt.logging.Logging" />

<set-property name="gwt.logging.logLevel" value="INFO"/>

<set-property name="gwt.logging.enabled" value="TRUE"/>

<set-property name="gwt.logging.consoleHandler" value="ENABLED"/>

<set-property name="gwt.logging.popupHandler" value="DISABLED" /><!-- LoggingPopup -->

<set-property name="gwt.logging.simpleRemoteHandler" value="DISABLED" />

This configuration cause logs to be printed only in to standard output, that is usually Eclipse console window.

Java code example:

import java.util.logging.Logger;

public final Logger logger = Logger.getLogger("test");

public void onModuleLoad() {

. . .

logger.info("Module is loading");

. . .

Or more conventional logger naming:

public final Logger logger = Logger.getLogger(MyModule.class.getName());

Note: Class.getSimpleName() and other similar methods (?) are not supported by GWT. You get run time exception if attempted. I often fall for this trick.

Now you can see your logs in console. Assuming you are in Developer Mode. Besides standard output, log messages are now printed to JavaScript console in Chrome or Chromium and Web Console in Firefox. I did not managed to see my logs in Internet Explorer 9, in its Developer Tools (F12), unfortunately. I am not much familiar with IE though.

LoggingPopup

Also known as popupHandler, after its configuration option name, or PopupLogHandler* - name creating an impression of a class, but no such class exists. The only relevant class is LoggingPopup and it does not implements a Logger Handler. It is a widget. It is a complex widget extending PopupPanel.

It is quite confusing since there are classes like ConsoleLogHandler or SimpleRemoteLogHandler with (mostly) matching names to logging properties and all of them are Handlers by nature. To make LoggingPopup a Handler, it needs to be wrapped using HasWidgetsLogHandler. Only after that it can be added to the Logger.

The LoggingPopup is by default enabled, the dialog box is always visible and is quite obtrusively visible, from the very start of the application, positioned on 0,0, potentially obscuring your content or breaking your layout. It is advisable step to switch it off in module configuration. However, the LoggingPopup has a valid usage. It can be shown only when needed and where needed. See my example below. See the screenshot.

Note: LoggingPopup is kind of competitor to my gwt-flexible-panel! It is draggable and resizable. And I would say my Panel is better ;)

*Note: see http://www.tutorialspoint.com/gwt/gwt_logging_framework.htm, clearly they mention PopupLogHandler in the listing table despite no such class exists.

How to explicitly show and position PopupLogger

When PopupLogger is disabled globally, it can be displayed only on explicit request, when is really needed. And you can also specify where to display it. It comes handy sometimes. See my example with logging mouse events. Originally the logger box overlapped both tested panels completely, they were not visible at all. Confusing.

Example of working code (for full see TwoClickMePanelsEventCaptureTestPage):

import java.util.logging.Logger;

import com.google.gwt.logging.client.HasWidgetsLogHandler;

import com.google.gwt.logging.client.LoggingPopup;

public final Logger logger = Logger.getLogger("test");

public void onModuleLoad() {

. . .

PopupPanel loggingPopup = new LoggingPopup();

loggingPopup.setPopupPosition(10, 240);

loggingPopup.setWidth("500px");

logger.addHandler(new HasWidgetsLogHandler(loggingPopup));

logger.info("Module is loading");

. . .

The class LoggingPopup is extends PopupPanel, there are plenty of styling methods to set width, height, top left position or to set CSS style name and externalize this to style sheet file.

The variant of class creation, using deferred binding :

HasWidgets loggingPopup = GWT.create(LoggingPopup.class);
cannot be used if set-property gwt.logging.popupHandler=DISABLED. Then NullLoggingPopup is created instead and using NullLoggingPopup cause various exceptions. It needs to be always class checked. See LogConfiguration::setDefaultHandlers(Logger l).

See in source code:

LogConfiguration::setDefaultHandlers(Logger l)

com.google.gwt.logging.client.LoggingPopup

Log message formatting

How to get custom log messages in a custom format, displaying full or shortened class name, timestamp format, something more compact then default “Fri Nov 02 15:10:09 GMT 2012”? Unfortunately, there is no straightforward way. There are no Patterns like in Log4J.

Blame Java Logging specification. It defines nothing about message formatting, only two simple formatters. All is left to vendor implementations and the GWT's provides only basic tools.

And GWT walks in Java Logging shoes, does not provides much either. If you look inside HtmlLogFormatter (GWT class), formatter customized for LoggingPopup (GWT class), it simply prints everything what is inside java.util.logging.LogRecord, field after field, decorating values with with HTML tags, including that stupid break line after INFO as you can see on my screenshots. That is not word wrapping. It is hard coded.

Basic Java Logging nor GWT logging is not that sophisticated as Log4J. Instead of a configuration option to set message formatting LayoutPattern in a nice DSL, like we do in Log4J, you have to implement Handler::setFormatter(Formatter f). See java.util.logging.Handler, java.util.logging.Formatter.

See: http://stackoverflow.com/questions/7504820/gwt-logging-patternlayout
Unanswered.

See: http://docs.oracle.com/javase/6/docs/api/java/util/logging/package-summary.html

Alternative GWT logging framework - gwt-log

Besides build in GWT logging there is an alternative – gwt-log. It is provided by external independent project. The official library is relatively new addition to GWT, added in late 2010 since GWT 2.1 M2, before that in times when developers were limited to GWT.log() only, see my first paragraph, in this time gwt-log sprung up as DIY project.

I have not tested this framework personally. Logging popup panel is also provided, judging from the screenshot it looks a bit more sophisticated then the default one. It can utilize Log4J on the server side, however on the client side, you are not much better of then with, no PatternLayout here either.

Also see “gwt-log vs GWT logging” in project forum.

Production mode

GWT's Production Mode is even more tricky. What do you think, you get from these lines?

public void onModuleLoad() {

    System.out.println("Greetings from System.out");

    GWT.log("Greetings from GWT.log()");

    logger.info("Greetings from GWT logger");

}

In DevMode, it prints:

Greetings from System.out
Tue Nov 06 13:40:38 GMT 2012 test
INFO: Greetings from GWT logger

In Production Mode: nothing!

The System.out.println() is silently ignored in Production Mode. GWT.log() does not do much anytime, no surprise here, and Logger is configured by default to use ConsoleLogHandler, option consoleHandler is by default enabled, but this handler does silently nothing in Production Mode.

Does not expect anything to see in console in Production Mode from the client side code. Not by default. Not unless you invest some more time configuring remote logging and make the message to be printed on server side, via some client server communication.

In client only projects - like mine I am working on - your only saviour is Firefox Web Console or Chromium JavaScript console, only way to see log messages. And you have to use proper GWT Logger. Not simple GWT.log(). Alternative is to use native JavaScript, native method, but you are better off trying GWT Logger framework. It is not sophisticated as Log4J, but saves you some “reinventing the wheel” time.

Note: GWT supports Java System.out and System.err (see here). They do work as expected in Developer Mode. They are silently ignored in Production Mode.

Some more screenshots

Minor bug in PopupLogger (Chromium):

 GWT Logger in action - Web Console, Firefox:

 GWT Logger in action - JavaScript console, Chromium:

Links

• https://developers.google.com/web-toolkit/doc/latest/DevGuideLogging
  official GWT logging library documentation
  
• http://code.google.com/p/gwt-log/ - alternative logging library gwt-log project page
  
• http://google-web-toolkit.googlecode.com/svn/javadoc/latest/com/google/gwt/core/client/GWT.html#log%28java.lang.String%29 – GWT.log() method javadoc
  
• http://stackoverflow.com/questions/4804336/gwt-logging-setup
  
• http://www.tutorialspoint.com/gwt/gwt_logging_framework.htm
  
• http://code.google.com/p/google-web-toolkit/source/browse/trunk/user/src/com/google/gwt/logging/client/LoggingPopup.java – LoggingPopup source code.
  
• https://groups.google.com/forum/?fromgroups=#!topic/google-web-toolkit-contributors/LLcWrwPCSfo - Peer review of the initial LoggingPopup code submission (5/11/2010). They were quite critique of the code.
  
• http://code.google.com/p/google-web-toolkit/source/browse/trunk/samples/logexample/src/com/google/gwt/sample/logexample/client/CustomLogArea.java - example of simpler custom logging widget based on VerticalPanel widget
• http://www.summa-tech.com/blog/2012/06/11/7-tips-for-exception-handling-in-gwt/
  - 7 Tips for Exception Handling in GWT. How to deal with stack traces in GWT. Featured article.