JAW Speak

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 – 6 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: 2 – 4 minutes

I had one gigantic directory of all my tagged and organized mp3 files. Problem is it was too big to use. This bloated my library and I have since not been able to fit my music on my laptop. I needed to manipulate mp3 files by genre and extract them out of this single directory to create smaller libraries. I spent all of about two minutes looking for a program to do this before deciding to write a script. Truthfully, it was worse: once upon a time I over-enthusiastically downloaded StepMania and 493 DDR games/songs. And then, I added all the songs into my music library. It’s a great party game, but not the kind of music I want to listen to.

Many implementations exist for reading ID3 tags. I first tried ruby-mp3info, however it didn’t read my custom genre (‘DDR’) so then I moved to id3lib-ruby which uses the c++ id3lib library.

This worked like a charm. I ran the script over all my directories and built up a list of the directories.

#!/usr/bin/env ruby
# find_music.sh
require "rubygems"
require 'id3lib'
require 'find'
require 'set'
 
ddr_files = []
ddr_dirs = Set.new
 
search_dir = '~/media/music/music_categorized'
 
Find.find(search_dir) do |file|
  next if file !~ /.*mp3$/
  mp3 = ID3Lib::Tag.new(file)
  next if mp3.genre != 'DDR'
  ddr_dirs << File.dirname(file)
  ddr_files << file   puts "%s, %s --> AT: %s" % [mp3.genre, mp3.album, file]
end
 
File.open('result-ddr-files.txt', 'w') do |f|
  f.write(ddr_files.join("\n"))
end
 
File.open('result-ddr-dirs.txt', 'w') do |f|
  ddr_dirs.each { |d| f.write("%s\n" % d)}
end

Next I reviewed the two output files, then ran the file result-ddr-dirs.txt in as an argument into this next script. That removed almost a gig of music from my library.

#!/usr/bin/env ruby
 
if (ARGV.length != 1)
  puts "Usage: #{__FILE__} input_file"
  exit(1)
end
 
destination="/home/jwolter/media/music/music_ddr_questionable_value/"
 
File.foreach(ARGV[0]) do |line|
  next if line.strip == ""
  cmd =  "mv \"#{line.strip}\" \"#{destination}\""
  #puts cmd
  `#{cmd}`
end

Bonus: In the process searching for this, I ran into the ID3 Tags RubyQuiz.

One of the nicest benefits of being a software engineer is I avoid doing boring manual tasks on my computer. Writing a script is more fun, and faster. I’ve got many scripts to automate file manipulation, online banking, and more. What bit of your automation scripts do you think is the most helpful?

Reading time: 5 – 8 minutes

Watching a movie that entertains is fun, one that teaches benefits you tomorrow, and ones that make you think in a new way are the best of all. I have a friend who says periodically it’s time to go to a conference, “in order to introduce randomness into the system.” Shake things up. Movies in “Cerebral” category in Netflix are a new way I found to do this. My hope is for comments and further recommendations of thought-worthy movies.

Bigger Stronger Faster is a documentary. Technically it’s about steroids in American culture, but it also raises the clear lack of consistency we treat other performance enhancers. The director Christopher Bell examines his brothers as they use steroids.

What is an ethical and responsible limit to how far you are willing to go for success? Is it okay to wake up in the morning and say you are destined for greatness – that somehow you were born to give something to the world? (And how far will you then go?) Is it okay to just become a normal, average, person?

• When Tiger Woods had laser eye correction to 20/15 vision, was that an unethical performance enhancement?
• How about professional musicians taking beta blockers to eliminate anxiety before performances and auditions?
• Athletes’ are dependent on cortisone shots (a legal steroid), yet should those be held equal to anabolic steroids?
• Red blood cell count can be increased by doping, taking EPO (details), high altitude training, or sleeping in an altitude chamber. Two options are illegal, two are legal. Should the end result (higher than natural RBC’s) be the determiner of ethics, rather than the mechanism used to reach it?
• The US Air Force gives fighter pilots speed (amphetamine) to perform better, is that a rational decision?
• He interviews a member of the Olympic Doping Committee and is told that routinely US Athletes are flagged for failing drug tests, but still allowed to compete.
• Attending a Chiropractor Anti-aging specialist Chris is able to say he suspects a hormone deficiency which leads to tests and results where no “healthy” range has been set enables him to get an Human Growth Hormone prescription – legally.
• Students are interviewed in how easy it is to get Adderoll (just tell your doctor you have trouble focusing, or have it passed around from friends). Are these and other “study drugs” (long but really interesting article) worth it? (Or, should everyone be taking them?)

I’m not ready to jump on the film’s open skepticism of “are steroids actually a health risk?” I don’t think they are naturally necessary and a cautious approach to my health comes intuitively. They cross my line of fair competition. Throughout sports and recreational fitness I was never tempted to try them. But maybe that was just because I wasn’t/didn’t want to become good enough to compete at the highest level?

But how far will we go for performance outside of sports? If you could close 70% more sales by taking “Synthesized Aquatic Maltose” (which I just invented), would you take it? Health Supplements in the US are not regulated to be proven healthy, the FDA has the job of proving them unhealthy.

Under the Dietary Supplement Health and Education Act of 1994 (DSHEA), the dietary supplement manufacturer is responsible for ensuring that a dietary supplement is safe before it is marketed. FDA is responsible for taking action against any unsafe dietary supplement product after it reaches the market. Generally, manufacturers do not need to register their products with FDA nor get FDA approval before producing or selling dietary supplements. — FDA on DSHEA

Therefore I could start selling this new supplement and require no doctors or nutritionists to even look at what my customers would start to ingest. Chris actually does this. Entertainingly, he picks up a few illegal day laborers, and invents a product and fills pills with his “proprietary blend” of powders. He does “before/after” pictures the same day at a photo shoot and can start selling this $40/bottle tonic. (Of course, manufacturing cost are under $5/bottle for him).

There is more, such as how Utah’s third largest economy ($2.5-$4 billion/year) is the health supplement industry (Nice article here about Utah’s supplement industry). Legislation from Utah’s Senator Orrin Hatch made for the passing of DSHEA, and continues to enable those too squeamish for “real steroids” to get something that promises the same benefits.

He goes on to show a breed of cow: Belgium Blue. Through 100 years of natural selection, these cows are deficient in Myostatin, a growth factor that limits muscle growth. Video below gives a peek. Researchers are looking to mimic that for fighting Muscular Distrophy in humans. See more freakish links about this gene mutation in humans, cows, or other animals. Note: Clip below from National Geographic, not from the movie.

Chris goes to say that Americans are all about Bigger Stronger Faster, and it’s un-American to be #2. We even have romanticized the concept, calling things bigger than expected as “Xyz, on steroids.” We must win, and we must win better than we previously won.

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: 2 – 3 minutes

Goal: scan in hundreds of duplex documents in a non-duplex scanner and combine into 1 pdf in automated way. Status: it was harder than it should have been, and not that automated, but this works.

Scan in the papers as pdf’s from your paper-feed equipped scanner. Scan them right side up, then flip over and scan the other sides. The two pdf’s will contain pages: 1, 3, 5… and 2, 4, 6…

Reverse the even pages.

#!/usr/bin/ruby
 
if __FILE__ == $0
  puts "Run this on ubuntu or somewhere that pdftk is easy to be had. (which isn't os x)"
 
  if ARGV.length != 1
    puts "Syntax: #{__FILE__} pdf_to_reverse.pdf"
    exit
  end
 
  pdf = ARGV[0]
  reversed_pdf = pdf.gsub(/\.pdf/i, "_reversed.pdf")
 
  page_count = `pdfinfo #{pdf} | grep Pages`.scan(/\d+/)
 
  `pdftk #{pdf} cat #{page_count}-#{1} output #{reversed_pdf}`
end

Lastly, combine the two pdf’s, shuffling every other page, starting with the odds. Note it has some dependencies on pdftk and pdfinfo for the reversing (which are excruciatingly difficult to install on os x), and os x (for the merging).

#!/usr/bin/ruby
 
if __FILE__ == $0
  puts "Run this on os x to shuffle two pdf's, where the
        even pages are already reversed (reverse them with other script)"
 
  if ARGV.length != 3
    puts "Syntax: #{__FILE__} odds.pdf reversed_evens.pdf output.pdf"
    exit
  end
 
  odds_pdf = ARGV[0]
  reversed_evens_pdf = ARGV[1]
  output_pdf = ARGV[2]
 
  # obviously, only works on os x.  I didn't see an easy way to combine pdf's
  # in pdftk or other tools I searched for
  `python '/System/Library/Automator/Combine PDF Pages.action/Contents/Resources/join.py' --output '#{output_pdf}' --shuffle '#{odds_pdf}' '#{reversed_evens_pdf}'`
end

References:

• pdftk – pdf toolkit, I could have installed with ports install pdftk, but that has a very long build dependency on gcj.

• Reversing pages with pdftk

• Another technique which would work if you didn’t need to reverse pages, using automator. And without automator (like I do with a script directly).

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.