JAW Speak

Reading time: 3 – 4 minutes

Today I was working with Kumar and Elian where we encountered production logs with dozens of NullPointerExceptions with no stack trace. We identified that the JIT compiler will optimize away stack traces in certain exceptions if they happen enough. The code below reproduces it. We are on jdk 1.6 (I don’t remember the minor version now).

public class NpeThief {
    public void callManyNPEInLoop() {
        for (int i = 0; i < 100000; i++) {
            try {
                ((Object)null).getClass();
            } catch (Exception e) {
                // This will switch from 2 to 0 (indicating our problem is happening)
                System.out.println(e.getStackTrace().length);
            }
        }
    }
    public static void main(String ... args) {
        NpeThief thief = new NpeThief();
        thief.callManyNPEInLoop();
    }
}

Run it as follows and the issue will appear (the stack trace length changes from 2 to 0):
javac NpeThief.java && java -classpath . NpeThief
javac NpeThief.java && java -server -classpath . NpeThief


How to fix it? The following options resolve it and it stays at 2, never going to 0 as length of NPE’s stack trace:
javac NpeThief.java && java -XX:-OmitStackTraceInFastThrow -server -classpath . NpeThief
javac NpeThief.java && java -XX:-OmitStackTraceInFastThrow -classpath . NpeThief
javac NpeThief.java && java -Xint -classpath . NpeThief
javac NpeThief.java && java -Xint -server -classpath . NpeThief

So the solution is to start with -XX:-OmitStackTraceInFastThrow argument to java which instructs the JIT to remove this optimization [1,2], or operate in interpreted only mode [3]. What is going on? [2]

The JVM flag -XX:-OmitStackTraceInFastThrow disables the performance optimization of the JVM for this use case. If this flag is set, the stacktrace will be available. (editor: or if the -Xint is set).

“The compiler in the server VM now provides correct stack backtraces for all “cold” built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.” http://java.sun.com/j2se/1.5.0/relnotes.html

How does this impact performance? I did extremely naive timing and time java [args] -classpath . NpeThief. It behaved as expected, with interpreted the slowest. Is that the solution?

No. We weren’t going to change production JVM options to resolve this, instead since our isolated example code above indicated that initial exceptions would throw with the full stack trace, we went back into older logs and grepped. Sure enough, right after we deployed there were exceptions appearing with the full stack trace. That gives us enough information where we can identify and fix the bug.

Notes:
[1] Related sun bug 4292742 NullPointerException with no stack trace
[2] Helpful StackOverflow discussion of NullPointerException missing stack traces
[3] -Xint: Operate in interpreted-only mode. Compilation to native code is disabled, and all bytecodes are executed by the interpreter. The performance benefits offered by the Java HotSpot VMs’ adaptive compiler will not be present in this mode.

Reading time: 3 – 5 minutes

We’re (stuck*) using maven on a project, and this means often the build doesn’t act like you’re expecting. Debugging requires knowledge about maven’s capabilities and less documented features. Here are some tips, please add more in the comments.

1. The -X flag shows debug logging, and tee it to a file which you then search for clues of what happened. This is great for verifying if a plugin actually ran, and what it did. Example: mvn -X install | tee out.txt
2. mvn dependency:tree (show the transitive dependencies of your dependencies) [1]
3. -Dtest=MyJavaTest (just use the name of the class, no package necessary)
4. mvn help:system (show environmental variables and system properties) [2]
5. mvn help:active-profiles (show the active profiles to be run)
6. mvn help:all-profiles (show all profiles maven reads)
7. mvn help:effective-pom (show the logical pom.xml being used)
8. mvn help:effective-settings (show the logical settings.xml which is being used)
9. mvn help:describe -DgroupId=org.apache.maven.plugins -DartifactId=maven-resources-plugin -Ddetail (show details about a plugin’s options)
10. -DskipTests this will skip running tests, but still compile it. or -Dmaven.test.skip=true which will skip compilation and execution of tests (use with judgment, I believe in testing)
11. If -X doesn’t show you the properties when you needed them, you can also use the ant-run plugin to echo a property value (does anyone else know a better way to do this in maven? Tell me what a property value is at the time of the plugin or goal executing?)
12. Run your tests paused in debug mode, waiting for a debugger to attach to port 5005 with mvn -Dmaven.surefire.debug test [4]

References:

• [1] http://maven.apache.org/plugins/maven-dependency-plugin/
• [2] http://maven.apache.org/plugins/maven-help-plugin/
• [3] http://cvs.peopleware.be/training/maven/maven2/debuggingPom.html
• [4] http://maven.apache.org/plugins/maven-surefire-plugin/examples/debugging.html
• http://puredanger.com/tech/2009/02/25/maven-tips/
• Personal experience

*Note: Initially I disliked the confusion and long, slow learning curve with maven. After working 8 months with maven and my colleagues Lucas Ward and Paul Hammant, I’m feeling much more comfortable and am generally okay with it. For small open source work, where you want a project quickly, but don’t want to spend a few hours with ant, I like it very much. For our large project, maven is fundamentally broken. Too much file copying is required, and manual intervention on a complex build is impossible, or extremely tedious. Running with our own build script we control could be dramatically more flexible.

On a mailing list Paul recently recommended a few other to consider:

Maven Dependency plugin
mvn dependency:tree
- shows me the transitive deps (say, “how the hell is MX4J being dragged into the build ?”)
mvn dependency:analyze
- show me unused, but declared dependencies.
There’s a ton of free capability to that plugin – http://maven.apache.org/plugins/maven-dependency-plugin/

An Atlassian dependency plugin
Atlassian wrote a plugin ( http://confluence.atlassian.com/display/DEV/FedEx+XI+-+Keeping+track+of+you+maven+dependencies ) that guards against undesired changing dependencies.

Maven Enforcer Plugin
A more intrusive way of guarding against deps that, say, should not make it into a war.  http://maven.apache.org/plugins/maven-enforcer-plugin/

What tips do you have? Please share them in the comments.

Reading time: 3 – 5 minutes

I’ve been heavily refactoring a large team’s codebase that stuffed many critical dependencies into request attributes. You see request.getAttribute() throughout the code, which is counter to dependency injection’s principles. Instead of getting what you want, be given it to you. We are moving to a more idiomatic way of using spring to inject things such as our custom Session object.

However, there was a lifecycle mismatch between some singleton interceptors which needed the session object, which is only request scoped. We had everything working, except one of those interceptors also needed the response object as a collaborator.

I had a spring instantiated non-controller bean that is request scoped, and I want to inject in two collaborators:

HttpServletRequest (which can be injected)
HttpServletResponse (which fails injection)

Here is my bean:
<bean id="sessionFactory" scope="request">
<aop:scoped-proxy/> <!-- scoped-proxy to get around the singleton requests injection of a request scoped object problem -->
</bean>


Here are the autowired fields:
@Autowired HttpServletRequest request;
@Autowired HttpServletResponse response;

Can I inject the response object in this bean?

This is the error I was getting:
[INFO] Caused by: org.springframework.beans.factory.BeanCreationExce ption: Error creating bean with name ’scopedTarget.sessionFactory’: Autowiring of fields failed; nested exception is org.springframework.beans.factory.BeanCreationExce ption: Could not autowire field: javax.servlet.http.HttpServletResponse com.example.web.SessionRequiring$SessionFactory.re sponse; nested exception is org.springframework.beans.factory.NoSuchBeanDefini tionException: No unique bean of type [javax.servlet.http.HttpServletResponse] is defined: Unsatisfied dependency of type [interface javax.servlet.http.HttpServletResponse]: expected at least 1 matching bean
[INFO] at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessAfterIn stantiation(AutowiredAnnotationBeanPostProcessor.j ava:243)

I navigated to GenericWebApplicationContext, which delegates to WebApplicationContextUtils.registerWebApplicationS copes(beanFactory), which then registers ServletRequest.class and HttpSession.class as injectable. But not the response object.

So here’s what I did, which works for me:

In web.xml add a filter that will store every ServletResponse in a threadlocal, which will be accessible only from your FactoryBean.

  <filter>
        <filter-name>responseInScopeFilter</filter-name>
        <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
        <init-param>
            <param-name>targetBeanName</param-name>
            <param-value>responseInScopeFilter</param-value>
        </init-param>
  </filter>
  <filter-mapping>
        <filter-name>responseInScopeFilter</filter-name>
        <url-pattern>/*</url-pattern>
  </filter-mapping>

Create the filter:

    /**
     * We need a filter to capture the HttpServletResponse object such that it can be injectable elsewhere in request scope.
     */
   public static class ResponseInScopeFilter implements Filter {
        // not the most elegant, but our spring commiter friends suggested this way.
        private ThreadLocal<HttpServletResponse> responses = new ThreadLocal<HttpServletResponse>();
        public void init(FilterConfig filterConfig) throws ServletException { }

        public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain) throws IOException, ServletException {
            HttpServletResponse response = (HttpServletResponse) servletResponse;
            responses.set(response);
            chain.doFilter(servletRequest, servletResponse);
            responses.remove();
        }

        /** Only to be used by the BeanFactory */
        private HttpServletResponse getHttpServletResponse() {
            return responses.get();
        }

        public void destroy() { }
    }

And also create the FactoryBean:

/** We need our own FactoryBean because Spring does not offer a way to
     * inject request scoped HttpServletResponse objects.
     * See http://forum.springsource.org/showthread.php?p=298179#post298179 */
    public static class HttpServletResponseFactoryBean implements FactoryBean {
        @Autowired ResponseInScopeFilter responseInScopeFilter;

        public Object getObject() throws Exception {
            return responseInScopeFilter.getHttpServletResponse();
        }

        public Class getObjectType() {
            return HttpServletResponse.class;
        }

        public boolean isSingleton() {
            return false;
        }
    }

Wire it all together in applicationContext.xml

<bean id="httpServletResponse" class="com.example.web.SessionRequiring$HttpServletResponseFactoryBean" scope="request"/>
<bean id="responseInScopeFilter" class="com.example.web.SessionRequiring$ResponseInScopeFilter"/>

Elsewhere I can now inject an HttpServletResponse object and it will be request scoped appropriately for this request. You can read more about this in my post on the spring forums.

Reading time: 1 – 2 minutes

Working on os x with Spaces means I want to read something on another space instead of waiting idly for a 50 second build. But, I don’t want to get distracted. So, I use Growl and growlnotify for notifications of the build’s completion.

#!/bin/sh
# this file is called: mvn (and is executable, and added to path before actual mvn command)

# capture all args passed in to forward to real mvn
ARGS=$*

# We need the client's specific settings.xml, so always specify it now
/usr/bin/mvn -s /Volumes/TrueCryptClient/opt/maven/conf/settings.xml $ARGS 

# when you have growlnotify installed and on your path, this will pop it up
# when the build is done
growlnotify -m "DONE: maven $ARGS"

Note: if you get this error from growlnotify: could not find local GrowlApplicationBridgePathway, falling back to NSDNC, it probably means growl is not started. Start up growl in your System Preferences.

Update: Thanks Cosmin, for the enhancement. Use this snipped in the script. Have an environmental variable for what the notify command is. And say what the build status is in the growl notify.:

if [[ -n $NOTIFY ]]; then
    ($command && $NOTIFY "Build Complete" && exit 0) || ($NOTIFY "Build Failed" && exit 127)
else
    $command
fi

Reading time: < 1 minute

I ran across this last week. It was marvelous when we saw what was happening, but entirely puzzling at first.

Boolean someFlag = complicatedLogicToFigureOutFlag();
Person person = new Person(someFlag);

Any signs for concern? How about if Person’s constructor is:

Person(boolean someFlag) {
    this.someFlag = someFlag;
}

Any warning signs?

Will it compile?

Read more for the full puzzler.

Read the rest of this entry »

Reading time: 4 – 7 minutes

I do not endorse branch based development. I prefer trunk based development. Specifically I like what my colleague Paul calls Branch By Abstraction, coined by Stacy Curl, and recently mentioned by Martin Fowler (All one time ThoughtWorkers, and 2 currently).

If you’re stuck with merging though, 3-way merges make it much easier. Doing it with subversion is easy. Instructions are for Linux.

1. apt-get or yum install kdiff3.
2. Edit your /etc/subversion/config and fin the line with diff3-cmd, set it to: diff3-cmd=/usr/local/bin/svndiff.sh
3. Next, create the file /usr/local/bin/svndiff.sh. See below for the script you’ll want to enter in it.

Now when you get a merge conflict you will choose M and merge will open in kdiff3. On the left is the base revision, in the middle is your working copy, and on the right the incoming change. This is a little more to look at, but it is invaluable when dealing with merges. I wouldn’t go back to 2 way diff ever again.

#!/bin/bash
 
# tim/paul: this is a copy of the file located at http://www.yolinux.com/TUTORIALS/src/svndiffwrapper.txt
#    modified to do a non-conflicting merge automatically. see #HERE#
 
# Return an errorcode of 0 on successful merge, 1 if unresolved conflicts
# remain in the result.  Any other errorcode will be treated as fatal.
# Author: Michael Bradley
 
#NOTE: all output must be redirected to stderr with "1>&2" as all stdout output is written to the output file
 
VDIFF3="kdiff3"
DIFF3="diff3"
DIFF="kdiff3"  
 
promptUser ()
{
    read answer
    case "${answer}" in
 
        "M"         )
        echo "" 1>&2
        echo "Attempting to merge ${baseFileName} with ${DIFF}" 1>&2
        $VDIFF3 $older $mine $theirs --L1 $labelOlder --L2 $labelMine --L3 $labelTheirs -o $output 1>&2
        bLoop=1
        if [ -f $output ]; then
            if [ -s $output ]; then
                #output succesfully written
                bLoop=0
            fi
        fi
        if [ $bLoop = 0 ]; then
            cat $output
            rm -f $output
            exit 0
        else
            echo "Merge failed, try again" 1>&2
        fi
 
        ;;
 
        "m"         )
        echo "" 1>&2
        echo "Attempting to auto-merge ${baseFileName}" 1>&2
        diff3 -L $labelMine -L $labelOlder -L $labelTheirs -Em $mine $older $theirs > $output
        if [ $? = 1 ]; then
            #Can't auto merge
            rm -f $output
            $VDIFF3 $older $mine $theirs --L1 $labelOlder --L2 $labelMine --L3 $labelTheirs -o $output --auto 1>&2
            bLoop=1
            if [ -f $output ]; then
                if [ -s $output ]; then
                    #output succesfully written
                    bLoop=0
                fi
            fi
            if [ $bLoop = 0 ]; then
                cat $output
                rm -f $output
                exit 0
            else
                echo "Merge failed, try again" 1>&2
            fi
        else
            #We can automerge, and we already did it
            cat $output
            rm -f $output
            exit 0
        fi
        ;;
 
        "diff3" | "Diff3" | "DIFF3"  )
        echo "" 1>&2
        echo "Diffing..." 1>&2
        $VDIFF3 $older $mine $theirs --L1 $labelOlder --L2 $labelMine --L3 $labelTheirs 1>&2
        ;;
 
        "diff" | "Diff" | "DIFF"  )
        echo "" 1>&2
        echo "Diffing..." 1>&2
        $DIFF $mine $theirs -L $labelMine -L $labelTheirs 1>&2
        ;;
 
        "A" | "a"   )
        echo "" 1>&2
        echo "Accepting remote version of file..." 1>&2
        cat ${theirs}
        exit 0
        ;;
 
        "I" | "i"   )
        echo "" 1>&2
        echo "Keeping local modifications..." 1>&2
        cat ${mine}
        exit 0
        ;;
 
        "R" | "r"   )
        echo "" 1>&2
        echo "Reverting to base..." 1>&2
        cat ${older}
        exit 0
        ;;
 
        "D" | "d"   )
        echo "" 1>&2
        echo "Runnig diff3..." 1>&2
        diff3 -L $labelMine -L $labelOlder -L $labelTheirs -Em $mine $older $theirs
        #Exit with return vaule of the diff3 (to write out files if necessary)
        exit $?
        ;;
 
        "S" | "s"   )
        echo "" 1>&2
        echo "Saving for later..." 1>&2
        cat ${mine}
        #Exit with return vaule of 1 to force writting of files
        exit 1
        ;;
 
        "Fail" | "fail" | "FAIL"   )
        echo "" 1>&2
        echo "Failing..." 1>&2
        exit 2
        ;;
 
        "H" | "h"   )
        echo "" 1>&2
        echo "USAGE OPTIONS:" 1>&2
        echo "  [A]ccept    Accept $labelTheirs and throw out local modifications" 1>&2
        echo "  [D]efault   Use diff3 to merge files (same behavior as vanilla SVN)" 1>&2
        echo "  [Fail]      Kills the command (not suggested)" 1>&2
        echo "  [H]elp      Print this message" 1>&2
        echo "  [I]gnore    Keep your locally modified version as is" 1>&2
        echo "  [M]erge     Manually merge using ${VDIFF3}" 1>&2
        echo "  [m]erge     Same as "M" but attempts to automerge if possible" 1>&2
        echo "  [R]evert    Revert to base version (${labelOlder})" 1>&2
        echo "  [S]ave      Same as 'I' but writes out rold, rnew, and rmine files to deal with later" 1>&2
        echo "  [diff]      Type 'diff' to diff versions $labelMine and $labelTheirsthe before making a descision" 1>&2
        echo "  [diff3]     Type 'diff3' to diff all three versions before making a descision" 1>&2
        echo "" 1>&2
        ;;
 
        *   )
        echo "'${answer}' is not an option, try again." 1>&2
        ;;
    esac
}
 
if [ -z $2 ]
then
    echo ERROR: This script expects to be called by subversion
    exit 1
fi
 
if [ $2 = "-m" ]
then
    #Setup vars
    labelMine=${4}
    labelOlder=${6}
    labelTheirs=${8}
    mine=${9}
    older=${10}
    theirs=${11}
    output=${9}.svnDiff3TempOutput
    baseFileName=`echo $mine | sed -e "s/.tmp$//"`
 
#HERE#
    diff3 -L $labelMine -L $labelOlder -L $labelTheirs -Em $mine $older $theirs > $output
    if [ $? = 1 ]; then
        #Can't auto merge
        #Prompt user for direction
        while [ 1 ]
        do
            echo "" 1>&2
            echo "${baseFileName} requires merging." 1>&2
            echo "" 1>&2
            echo "What would you like to do?" 1>&2
            echo "[M]erge [A]ccept [I]gnore [R]evert [D]efault [H]elp" 1>&2
            promptUser
        done
    else
        #We can automerge, and we already did it
        cat $output
        rm -f $output
        exit 0
    fi
else
    L="-L"         #Argument option for left label
    R="-L"         #Argument option for right label
    label1=$3       #Left label
    label2=$5       #Right label
    file1=$6        #Left file
    file2=$7        #Right file
 
    $DIFF $file1 $file2 $L "$label1" $L "$label2" &
    #$DIFF $file1 $file2 &
    #wait for the command to finish
    wait
fi
exit 0

Note: I also posted this to a gist on github: svndiff.sh.

Reading time: 4 – 7 minutes

My last client our team worked with had a large ecommerce operation. Yearly revenue in the new site is in the high single digit billions of dollars. This necessitates extremely high availability. I will draw an initially favorable looking configuration for this high availability (“beautiful spiderwebs”), but then tear it apart and suggest an alternative (“Thicker Stack on One Hardware”).

1. “Beautiful Spiderwebs” – Often Not Recommended

Here’s one common way people could implement high availability. Notice how there are always multiple routes available for servicing a request. If one BIG IP goes down, there is another to help. And this could be doubled with multiple data centers, failed over with DNS.

The visible redundancy and complexity in one diagram may be appealing. One can run through scenarios in order to make sure that yes, we can actually survive any failure and the ecommerce will not stop.

So then what could make this my Not Recommended option?

2. Martin’s Reminder how to Think About Nodes

Fowler reminded us in Patterns of Enterprise Application Architecture how to look at distribution and tiers. For some reason people keep wanting to have certain “machines running certain services” and just make a few service calls to stitch up all the services you need. If you’re concerned about performance, though, you’re a looking for punishment. Remote calls are several orders of magnitude greater than in process, or calls within the same machine. And this architectural preference is rarely necessary.

One might lead to the first design with the logic of: “We can run each component on a separate box. If one component gets too busy we add extra boxes for it so we can load-balance our app.” Is that a good idea?

The above is not recommended:

A procedure call between two separate processes is orders of magnitude slower [than in-process]. Make that a process running on another machine and you can add another order of magnitude or two, depending on the network topography involved. [PoEAA Ch 7]

This leads into his First Law of Distributed Object Design: Don’t distribute your objects!

The solution?

Put all the classes into a single process and then run multiple copies of that process on the various nodes. That way each process uses local calls to get the job done and thus does things faster. You can also use fine- grained interfaces for all the classes within the process and thus get better maintainability with a simpler programming model. [PoEAA Ch 7]

3. “Strive for Thicker Stack on One Hardware Node” – Recommended

Observe the recommended approach below. There is still an external load balancer, but after a request is routed to an Apache/Nginx/etc front end, you’re all on one* machine.

If one tier fails on a node, pull the whole node out from rotation. Replace it. And re-enter it in the mix.

Your companies teams have worked together to be able to deploy modular services. So when your ecommerce site needs a merchant gateway processing service, you can include that (library or binary) and run it locally on your node, making a call through to it as needed.

Services are also simpler to deploy, upgrade and monitor as there are fewer processes and fewer differently-configured machines.

(* I understand there may be the occasional exception for remote calls that need to be made to other machines. Possibly databases, mcached obviously third party hosted services, but the point is most everything else need not be remote.)

4. But, Practically Speaking How Far Do We Go?

A caveat first: these benefits get pronounced as you have more and more nodes. (And thus, more and more complex of spiderwebs of unnecessary failover).

Should there be a database server running on each node? Probably not at first. There is a maintenance associated with that. But after sharding your database and running with replication, why not? This way if a node fails, you simply pull it out and replace it with a functioning one.

5. Checklist of Takeaway Lessons

1. Keep it local. Local calls orders of magnitude faster than remote calls.
2. Make services modular so they don’t need to be remote, yet still have all the organizational benefits of separate teams.
3. Simplicity in node-level-redundancy is preferred over tier-level-redundancy.

Often, people think of high availability with terms such as the following: Round Robin, Load Balancing, and Failover. What do you think of? Leave a comment below with how you meet the trade-offs of designing for HA as well as architectural decisions of low latency.

Reading time: 2 – 4 minutes

Does it make sense for practicing software engineer to go to grad school? Technologies change rapidly, and so do our clients and projects. So we have constant opportunities to learn and most importantly to apply ourselves in building production systems. Bonus: putting production systems live into the world teaches a lot more than a good grade in an exam.

I once remember in undergrad my friend getting an offer at Microsoft, but he was torn on going to grad school. Basically his sponsor there told him graduate degrees aren’t worth much, and I’d go so far as to suggest that they can be less useful than varied and interesting real project work.

“Sure, go to cs grad school if it makes your ego feel better, but don’t do it for your career.”

Oh?, my friend said, and if my memory serves me, he went on to grad school.

Everyone’s situation is different. However this is something I’ve struggled with for the last several years: does it make sense to step back and do research, and to do computer science-y things instead of day to day project delivery? Maybe. Maybe not. I’ve more or less made my decision for now. But every few months the nagging urge comes back.

I found these posts helpful for framing my decisions.

1. http://jxyzabc.blogspot.com/2008/08/cs-grad-school-part-1-deciding-to-apply.html (the whole multi-part series, actually)
2. http://www.stanford.edu/~pgbovine/grad-school-app-tips.htm – says how it is all about research, and really Ph.D. applications are a job application, where you are applying to do research, rather than a place to be taught. (MBA, Med School, and other higher education avenues are a place you pay to be taught.) Masters degrees are different, but generally still have the same theme “you’re getting paid, so you better love (your) research.”

Update: Mark Needham commented about two pointed posts from Penelope Trunk’s blog. Worth reading.

1. http://blog.penelopetrunk.com/2008/06/18/seven-reasons-why-graduate-school-is-outdated
   Grad School isn’t needed, and it causes more harm than good. Too much focus. Careers change too much. Experience trumps prolonged childlike academic sheltering. (Note: My opinion isn’t so harsh. Your grad school might not apply, it depends on what you want to do).
2. http://blog.penelopetrunk.com/2009/02/03/dont-try-to-dodge-the-recession-with-grad-school/
   She prefers learning by doing, and suggests a feeling of “being lost” is actually helpful for growing.

Reading time: 4 – 6 minutes

private AsyncCallback asyncCallback = new AsyncCallback() {
  public void onFailure(Throwable caught) {
    Window.alert("An error occured, please try again. \n" + caught.getMessage());
  }
  public void onSuccess(PackageDto pkg) {
    firePackageUpdate(pkg); // throw an event in here that is handled by a
                            // listener, which is the gui code and which has no logic
                            // (logic is in the controller!)
  }
};

java.lang.ExceptionInInitializerError
Caused by: java.lang.UnsupportedOperationException: ERROR: GWT.create() is only usable in client code!
   It cannot be called, for example, from server code.  If you are running a unit test, check that your test
   case extends GWTTestCase and that GWT.create() is not called from within an initializer or constructor.
at com.google.gwt.core.client.GWT.create(GWT.java:91)
at com.google.gwt.user.client.Window.(Window.java:230)
... 28 more

1. Implement the AsyncCallback<T> interface with BaseAsyncCallback<T> , and implement the onFailure() to call Window.alert(). In tests, I would subclass and override onFailure() in tests, preventing the Window.alert() from executing. I generally don’t like subclassing for tests, so I wasn’t too keen on this.
2. Implement the AsyncCallback<T> interface with a class BaseAsyncCallback<T>, but this time take in a constructor parameter, FailureHandler (which would be an interface or class of my own.) Then in onFailure(), delegate to the FailureHandler field. In tests, pass a different FailureHandler implementation or subclass, to avoid calling the GWT widget code.
3. The recommended solution is to treat this the same way I deal with onSuccess(). Tell a listener that a failure event occurred, and let it handle it.

Reading time: 3 – 4 minutes

Update: Added a snippet so that you can easily assert a message was contained in the logged messages.

Frequently logging is not viewed as “important” by engineers as, say, the logic for refunding a customer’s purchase. The customer’s won’t mind, after all, if we forget to log something right? Maybe so, until there are problems and the operational team supporting your application has very little ability to diagnose problems.

I propose logging should be viewed as another user interface, and thus needs its’ own set of acceptance and unit tests. This makes for more tedious and up front work for development teams — however I want to survive in production without a pager going off, and with fewer late night scrambles to ship patches.

Imagine a class that has logic associated with logging. Below you will see a unit test verifying logging statements are correct. Often logging uses statics, and as Misko has said, statics are a death to testabilty. With Guice you can easily inject loggers automatically for the class under construction. This method gets around most of the issues with static loggers, although I still despise statics everywhere.

This is a basic example, but the point is to understand how to hook into appenders and add/change one to use a test appender.

package com.jawspeak.common.testing;
 
import com.google.common.collect.Lists;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;
 
import java.util.List;
 
/**
* Use me for spying on test logs and making asserts against them.
*
* Example how to use:
*        final SpyLoggerAppenderForTesting spyAppender = new SpyAppenderForTesting();
*        final Logger logger = Logger.getLogger(MyClass.class.getName());
*        try {
*            logger.addAppender(spyAppender);
*            // do something
*            assertEquals(Lists.newArrayList("Attempted to read such-and-such, but could not: oops"), spyAppender.getMessagesLogged());
*        } finally {
*            logger.removeAppender(spyAppender); // clean up global state
*        }
*/
public class SpyLoggingAppenderForTesting extends AppenderSkeleton {
  private List messages = Lists.newArrayList();
 
  protected void append(LoggingEvent loggingEvent) {
    messages.add(loggingEvent.getRenderedMessage());
  }
 
  public List getMessagesLogged() {
    return messages;
  }
 
  public boolean doMessagesContain(String snippet) {
      boolean isFound = false;
      for (String message : messages) {
          if (message.indexOf(snippet) >= 0) {
              isFound = true;
          }
      }
      return isFound;
  }
 
  public void close() { }
  public boolean requiresLayout() { return false; }
}

Here’s an example test where we make use of it. Note that we didn’t assert the lists are exactly the same, because in this project we were also using aspects to do logging, and depending on if you ran with or without the aspects enabled, a different number of logging messages would be created.

package com.jawspeak.common.utility;
 
import com.google.common.collect.Maps;
import com.jawspeak.common.testing.SpyLoggingAppenderForTesting;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.junit.After;
import static org.junit.Assert.*;
import org.junit.Before;
import org.junit.Test;
 
import java.util.LinkedHashMap;
import java.util.List;
 
public class SessionSizeLoggingTest {
private SpyLoggingAppenderForTesting spyAppender = new SpyLoggingAppenderForTesting();
private Logger logger = Logger.getLogger(SessionSizeLoggingTest.class.getName());
private Level oldLoggingLevel = logger.getLevel();
private SessionSizeLogging sessionSizeLogging = new SessionSizeLogging();
 
  @Before
  public void setUp() {
    logger.addAppender(spyAppender);
    logger.setLevel(Level.TRACE); // set the level in case a log4j.properties or log4j.xml disables this level of logging
  }
 
  @After
  public void tearDown() {
    logger.setLevel(oldLoggingLevel);
    logger.removeAppender(spyAppender);
  }
 
  @Test
  public void logBytesWhenUnprintable() throws Exception {
    LinkedHashMap map = Maps.newLinkedHashMap();
    map.put("key", new String(new byte[] { 1, 31, 127, -97}, "ISO-8859-1"));
    String sessionId = "abc123";
    sessionSizeLogging.logSessionSize(logger, sessionId, map);
    List messagesLogged = spyAppender.getMessagesLogged();
    assertTrue(spyAppender.doMessagesContain("Session Size for session id: " + sessionId + " (approx. total " + (7 + 3 + 1 + 4 + 1) + " bytes)"));
     // or use
    assertTrue(messagesLogged.contains("  key[   3 bytes]                            key  -->  value[   4 bytes] '\\u0001\\u0031\\u0127\\u0159'"));
  }
 
  // .. many more tests
}

This is a trick that I don’t see written about too much, but I recommend it often. And, I’d love to have some readers post enhancements, links, and take testability further with respect to logging.