thread dump

The previous couple of posts were related to using Apache Camel in a healthcare integration setting.  The HL7 support in Camel is built on the HAPI library which provides Java classes for most of the HL7 v2 variants, plus MLLP support.  So in integration terms, HL7 can be considered a combination of an endpoint type (the MLLP/TCP protocol) and a message format (the HL7 ER7 or XML representation).

The Camel architecture nicely isolates endpoint-types and message-structure types in Components and DataFormats, respectively.  A Component is something which knows about a specific communication mechanism or protocol: in the case of HL7, the Camel HL7 Component knows how to exploit the underlying Apache Mina library to exchange delimited text messages using the HL7 protocol.  The Component also acts as a factory for Camel Endpoint objects: it hands out individual Endpoint objects, each of which represents an instance of the endpoint-type implemented by the Component. Camel DataFormat objects marshal / unmarshal byte-streams or strings to / from Java objects of some type.  This makes it much easier to build content-based routes in Camel.

HL7 ACK / NAK Messages

In the previous post, one of the issues I had to deal with in the example route was returning an ACK or a NAK to the message originator. The HL7 protocol uses a positive-acknowledgement scheme: receivers will ACKnowledge (ACK) messages they understand and can process, and will Negatively AcKnowledge (NAK) anything else.  The HAPI library provides support for this in the makeACK method of the DefaultApplication class.  Unfortunately, this is less helpful when we need to return a NAK.

Recall that the first part of my route was checking to see whether the right kind of message has been received. In the sample, I was testing just the message type (MSH-9.1) and the trigger event (MSH-9.2) fields.  In reality, you would probably also want to check that the sender was using the same version of HL7 as you are expecting: you can do this by examining the value of field MSH-12. It will become clear why this is important, below.

Suppose the inbound message fails the MSH-9 test. The otherwise() clause in my little route will send the HL7 data (unmarshalled from the stream) to the badMessage() method on my handler bean.  This method expects a single argument of type ca.uhn.hl7v2.model.Message, i.e. a generic HAPI HL7 message object.  The argument can’t be of a more specific type than this because the Camel route builder cannot know in advance what will be received and unmarshalled from the endpoint; it can only assume it will be a HAPI Message.

Constructing an ACK

In the badMessage method, I need to construct a HL7 NAK message to be returned to the caller. HL7 ACKs and NAKs share the same structure: we just need to change the value of one field (and optionally add a diagnostic message) to indicate NAK. The obvious solution is to call DefaultApplication.makeACK, mentioned earlier, and modify the returned structure as necessary.  MakeACK’s single argument is a single Segment, the intention being that the caller passes-in the MSH segment of the original inbound message:

Message makeACK(Segment inboundHeader)

The reason for this is that the makeACK method needs some values from the inbound MSH segment to populate fields in the Message Acknowledgement segment (MSA) of the ACK correctly. An HL7 ACK (or NAK) must be associated with the original message (i.e. the inbound message being ACK’d or NAK’d) so that the originator can distinguish which of its outbound messages is being acknowledged or rejected. This is done using the Message Control ID, which is field 10 of the MSH segment.

But remember where we are in the Camel route: we have an invalid message in our hands. We don’t know the exact class-type of the inbound message object so we can’t cast the Message to a specific type. And the Message interface itself doesn’t provide a way to extract the MSH segment. So how are we going to call makeACK(Segment)?

We cannot simply new-up an instance of some specific message type (e.g. a version 2.3 ORM^O01) and use its MSH segment as the makeACK argument:

    // Assume ca.uhn.hl7v2.model.v23.*
   
    ORM_O01 orm = new ORM_O01();

    ACK ackMsg = (ACK)DefaultApplication.makeACK(orm.getMSH());        // <– Bang!

    // Set MSA.1 to Application Reject (AR)
    ackMsg.getMSA().getAcknowledgementCode().setValue(”AR”);

    // etc.

This will compile, but won’t work. The manufactured ORM_O01, despite being an instance of a specific version of HL7, is not properly constructed, in several ways. First, MSH-12.1 will not contain “2.3″, which is surprising, given that HAPI should be able to populate MSH-12.1 for a new message instance. If we pass the ORM_O01 MSH to makeACK, it tries to get the value of MSH-12.1 but finds a null. This causes makeACK to fall-back to creating and returning an ACK for version 2.4 of HL7 (this is baked-in to the HAPI code – I’m not sure if this is an arbitrary HAPI design decision, or to do with the HL7 spec). And of course we get a ClassCastException at run-time as a result, because we are expecting a v2.3 object.

But even if this did work, isn’t it ugly? We’d be baking-in a version of HL7 because we must choose a specific ORM_O01. So how do we create the ACK structure, and how can we make our code work for any version of HL7 supported by HAPI?

Terser to the rescue

Fortunately, HAPI provides a handy utility class for parsing and unparsing HL7 messages of arbitrary versions – the Terser. This will let us get hold of the MSH segment from the original message, so we could at least call makeACK with the original MSH:

    // This still depends on the ackMsg decl. being for the same specific version
    // as the original message.
    Terser t = new Terser(originalMsg);
    Segment msh = t.getSegment(”MSH”);
    ackMsg = (ACK)DefaultApplication.makeACK(msh);
    ackMsg.getMSA().getAcknowledgementCode().setValue(”AR”);

Now when we call makeACK we are passing-in a valid MSH so it will extract the HL7 version number and dynamically create the correct ACK class, using Class.forName.  But as the comment says, this stilll only works if the compiled-in ACK declaration matches the returned ACK message version. We need to lose the compiled-in ACK declaration, but still find a way to populate the ACK message’s MSA segment with the right values.

Fortunately, we can use the Terser to set the field values in a version-independent way. This is exactly what DefaultApplication’s static methods makeACK and fillResponseHeader do.  So I used a combination of the Terser and the guts of DefaultApplication.makeACK to create a couple of helper methods which do the right thing.  I’ve put the source code on this page in my Google site, for anyone who wants to use it.

Thanks to Claus Ibsen for such a helpful response to my previous post.  As Claus points out, the answer is to use a Camel helper class, PredicateBuilder, which contains a bunch of useful static combinator methods.  Claus shows in his post how to implement my trivial conjunction easily using the and() method.  Note the generic signatures of all these helper methods, e.g.

It’s taking a while for me to grok Camel; here is a couple of things I’m not yet clear about:

It’s probably not necessary to start this article with a mini-lecture on why logging, like unit-testing, is a Good Thing, so all I will say is logging is important not only during development but also invaluable in diagnosing runtime problems, once a solution is delivered and running. From here on I’m going to assume you’re convinced.

So, you know you should be logging, but how? And which of the many logging frameworks should you use? This article sets out to answer the first question, showing you how to get started logging in Java, using the NetBeans IDE, and offers an opinion on the answer to the second question.

There are several well-established ways to do logging in Java but the best approach I have come across so far is to use slf4j (the Simple Logging Facade for Java) for all logging statements in source code. The slf4j facade interfaces are completely independent of any specific logging implementation. The binding between the slf4j facade interfaces and a concrete logger implementation is done statically when the application jar is compiled: there is no runtime trickery involved (e.g. using class-loaders).

This approach allows you to replace one logging implementation with another without altering any of your logging code, just by binding to a different concrete logger (i.e. referencing a different logger implementation jar).

Splitting the logging job into two in this way means you need two references in your Java project, in order to use slf4j:

1. a reference to the slf4j API itself, which provides the interfaces you will use exclusively in your logging code.
2. a reference to a concrete logging implementation, which your logging code will call via the slf4j facade.

As the slf4j interfaces must be bound to a concrete logger implementation, you need to choose which logger to use. I have chosen Logback, which appears to be an improved version of log4j, one of the more efficient Java logging solutions.

This article describes what you need to do to start logging using this combination. I’m going to assume that you understand the value of logging, and know a little about log statements and logging levels: these are common to all modern logging frameworks, so I won’t cover them in detail.
Logger Libraries

Download slf4j and logback. Extract the distribution archives to wherever you keep your libraries. Then, in NetBeans, create libraries (via Tools/Libraries) for both distributions.

• For slf4j, include the slf4j-api.jar. The precise name of the jar file will depend on the version you download: mine is slf4j-api-1.5.0.jar
• For logback, you need logback-core.jar and logback-classic.jar. Again, precise file name depends on version e.g. logback-core-0.9.9.jar

You could create a combined library as a convenience for simple projects, if you know that you will frequently want to use the same concrete logger with the facade. However, bear in mind that for projects which build libraries or components used in other projects, you should only reference the slf4j library: the logger implementation binding should be done by the application which uses your component.

The source code for this tutorial assumes two NetBeans libraries, one for slf4j and the other for logback.

Adding Logging To Your Code

In your NetBeans application project, add references to the slf4j and logback libraries. To start logging from your code, you need to do the following things:

1. Initialise a logger reference in every class you wish to log from.
2. Add Import statements for the required slf4j types
3. Add logging statements to your code.

Refer to the source code with this article. Look first at the Main class: the first declaration in the class is for the logger:

private static final Logger _log = LoggerFactory.getLogger(Main.class);

Notice that this logger is declared static: this is because Main houses the static main() application method, so the logger must be static for it to be referenced from the main method. Above, in the imports section, you will see the two imports necessary to use slf4j:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

Now open the slf4j-sample-lib project, a trivial sample library which the main application references. Look at the StringReverser class, and notice that the logger is declared slightly differently:

private final Logger _log = LoggerFactory.getLogger(this.getClass().getName());

This is a non-static declaration: only non-static methods will have access to this logger. If you look carefully at the declaration, you’ll spot that this one is portable: it doesn’t contain the class name explicitly. This declaration can therefore be pasted without modification into any class, but remember that this is non-static, so will not be usable from any static methods in the class.

As the static logger is usable from everywhere (non-static and static contexts), wouldn’t it be convenient to have that declaration added automatically in every new class you create? Perfectly possible, in NetBeans. To include the logger declaration in your NetBeans source code template, go to Tools / Templates, open the Java branch and select Java class and click Open in Editor. You’ll see the Java class template source, complete with template parameters for the class name and some other stuff I’ll ignore here. All we need to do is add a single line to the class skeleton:

public class ${name}
{
private static final Logger _log = LoggerFactory.getLogger(${name}.class);

}

If you save the changes to your template and create a new class in NetBeans, you’ll see the logger declaration with the correct class name parameter value has been added to the source. You could even add the necessary import statements to the template.

But the overhead of including the logger declaration is low (just one simple line), and NetBeans will take care of the imports for you (use Fix Imports with Ctrl-Shift-I), so you may decide it’s not worth adding these lines to your templates.

Static versus Non-static Loggers

There’s one more difference between static and non-static loggers which you should at least be aware of. If you declare the logger static, there will be exactly one instance of the logger retrieved for the class, shared across all instances. As the logger reference is shared, memory is allocated just once and the logger is initialised just once, rather than once per object. This is not usually a problem, but you should be aware that the same logger reference will be shared across every instance of the class.

When declared non-static, every instance of your class will incur the memory and initialisation cost for the logger reference variable. For the vast majority of classes this will not be a significant overhead, but again you should be aware of the tradeoff. Note that within the same application, retrieving a logger by a given name will always return the same logger object: using a non-static logger reference does not mean that every instance of a class gets a new logger object of its own.

For a complete account of this issue, you should consult the slf4j documentation which covers this. Read this section of the online documentation.

Logging Statements

As I said in the introduction, I’m assuming you are somewhat familiar with logging. If not, go back and read the material on the slf4 and logback sites, and follow-up the references there.

Use the logger method appropriate to the level you wish to log at, for example:

_log.info(”‘{}’ reversed is ‘{}’”, instance.getValue(), instance.reverseValue());

Possibly the most important piece of advise I can give here is to consider the cost of logging carefully, especially debug-level logging. The actual call to the logger object is not usually the dominant cost in debug logging: you are likely to be constructing moderately large strings to output, and the cost of preparing these may be where you incur the biggest cost. Consider a line such as this:

_log.debug(”Debugging string: “ + ExpensiveGetter());

The runtime cost of constructing the string argument to this logging statement will always be incurred, whether the log-level is set to debug or to some other (less-detailed) level. Clearly that’s an undesirable, and fortunately there is a very simple coding idiom we can use to avoid this cost:

if (_log.isDebugEnabled())
{
_log.debug(”Debugging string: “ + ExpensiveGetter());
}

Simply guard the debug log statements with a test for the current (runtime) level of the logger. This does add a little source code; it is possible to reduce simple statements like the one above to a one-liner but I generally avoid this, valuing clarity over concision.

The cost of the debug statement will now be reduced to a simple boolean test, which is much more acceptable.

Configuring Logback

If you build and run the sample project accompanying this piece, you’ll see the log statements are written to the console. This is the default behaviour for most logging solutions, logback included. In most production situations you will probably want to direct your log messages somewhere else, to a file for example.

In common with other logger implementations (such as log4j) the logback subsystem can be controlled through an XML configuration file. For a complete treatment of the options and syntax, you’ll need to refer to the logback documentation and in this article I’ll give a superficial account of a simple but usable configuration.

Here is the configuration file:

<?xml version=”1.0″ encoding=”UTF-8″?>
<!–
Document : logback.xml
Created on : 25 February 2008, 22:40
Author : Roger
Description:
Configuration for logback logging framework.
For this file to be read by logback at runtime, it must be placed
on the classpath.
–>
<configuration>
<appender class=”ch.qos.logback.core.rolling.RollingFileAppender” name=”RootFileAppender”>
<file>application-log.txt</file>
<append>true</append>
<filter class=”ch.qos.logback.classic.filter.ThresholdFilter”>
<level>debug</level>
</filter>
<rollingPolicy class=”ch.qos.logback.core.rolling.FixedWindowRollingPolicy”>
<fileNamePattern>application-log.%i</fileNamePattern>
<maxIndex>2</maxIndex>
</rollingPolicy>
<triggeringPolicy class=”ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy”>
<maxFileSize>100000</maxFileSize>
</triggeringPolicy>
<layout class=”ch.qos.logback.classic.PatternLayout”>
<pattern>%d{yyyy-MM-dd HH:mm:ss},%p,%c,%F,%L,%C{1},%M %m%n</pattern>
</layout>
</appender>
<root>
<level value=”debug”/>
<appender-ref ref=”RootFileAppender”/>
</root>
</configuration>

Although this is quite a simple configuration file, there’s a lot of information in there and to understand it all fully you will need to study the logback documentation. I’ll skim over the most important bits here and leave the rest to you.

Appenders are the part of the logging engine which actually write the log messages somewhere. You can choose from many different appenders – my favourite is the RollingFileAppender which writes to a text file and ‘rolls-over’ to a new file once the existing file passes a certain size, declared in the triggeringPolicy element. The file element declares the filename, and the rollingPolicy/fileNamePattern declares the filename pattern to use for old log files, as the file rolls-over.

Layouts define the format of the messages written to the log appender. I’ve gone with a standard pattern which appears in the logback documentation: please consult the logback documentation on format strings to discover all the options here. Essentially, every log statement will include the date and time, and the origin of the log message, including the line number.

So the net effect of this configuration is that logback will write all log activity out to the file application-log.txt in the working directory, rolling the file when it reaches the size limit I have set (roughly 100k).

Logback and the Classpath

As explained in the logback documentation, if you want to configure logback with an XML file then the file must be present on the classpath of the application, otherwise logback will not find it and will fall-back to console logging.

If you examine the source code accompanying this piece you’ll see that I have placed the logback.xml file in the root of the source folder (src). In the NetBeans project, this is the ‘default package’: the name of anything placed here will have no namespace prefix. When NetBeans builds a Java application, it will compile any Java sources it finds in src and all its subdirectories, and will also by default include everything it finds in the root folder in the jar file. To prove this to yourself, go into the src folder, create an arbitrary file, say ‘fred.txt’, and rebuild the project. Now open the NetBeans Files view (Ctrl-2 will open this if it’s not already visible), locate the ‘dist’ folder and open the tree until you locate the slf4j-sample.jar file. The NetBeans file view allows you to browse the jar file contents – just open the tree to the next level:

And there are the two files, logback.xml and fred.txt, packed into the root of the jar. We don’t need fred, so delete the file and rebuild the jar.

So the source hierarchy in NetBeans contributes to the runtime classpath, and the ‘dist’ folder is where NetBeans writes out all artifacts resulting from a build. As the NetBeans documentation (and the generated readme) tells you, you can distribute your application by zipping-up and publishing the contents of the dist folder.

Let’s run the application. Open a terminal window in the dist folder and type:

java -jar slf4j-sample.jar

The program should run, but nothing should be written out to the console. Instead, an application-log.txt file should appear in the dist directory. Open that file and you will see the result of the logging statements. Logback has obviously located the configuration file and applied the settings.

If you’re thinking ‘job done’ at this point, not so fast! Just consider how logback has located and loaded the XML file. The logback XML file is packed into the (executable) jar file which is the main artifact generated by the build. When the Java runtime runs this jar it first examines the jar’s manifest (the MANIFEST.MF file in the META-INF folder inside the jar), which looks like this (from the sample application jar):

Manifest-Version: 1.0
Ant-Version: Apache Ant 1.7.1
Created-By: 11.0-b15 (Sun Microsystems Inc.)
Main-Class: slf4jsample.Main
Class-Path: lib/logback-classic-0.9.9.jar lib/logback-core-0.9.9.jar l
ib/slf4j-api-1.5.0.jar lib/slf4j-sample-lib.jar
X-COMMENT: Main-Class will be added automatically by build

The runtime looks for the entry point of the program (the qualified name of the class containing the main method) and initialises the classpath from the Class-Path setting. Implicitly, ‘.’ (the root of the jar structure) is also on the runtime classpath.

What this means is that when the logback system goes looking for logback.xml it will find the copy in the jar file. Consider the function of the logback.xml file: the users of the application will almost certainly want to configure the log behaviour themselves rather than accept the settings you have baked-in to the copy of logback.xml inside the jar file.

So, we want to distribute our default logback.xml file but not have it baked-in to the jar file: what to do? Having it in the source classpath is convenient because it appears in the NetBeans project view so we can view and edit it from inside the IDE. However, we don’t want it packed into the jar, but we do want it on the runtime classpath. How can we satisfy all of these constraints?

We can achieve this with two simple steps:

1. To prevent NetBeans including the XML file from the jar file, we exclude logback.xml from the list of source artifacts that NetBeans considers as jar contents.
2. Add a step to the build process which copies logback.xml into the dist folder, placing it next to the jar file.

For step (1), open the NetBeans project properties dialog and navigate to the Packaging subsection, below Build. Add “logback.xml” to the list of Excluded files:

If you rebuild the application, then use a zip tool or archive manager to open the resulting jar file, you’ll see that the logback.xml file is no longer included. There is more help on excluding content from your jar in this page of the NetBeans documentation.

For step (2) we need to arrange for the logback.xml file to be copied into the dist folder during the build process. To do this, we will add a very simple custom build-step to the NetBeans build process. As you probably know, NetBeans uses Apache Ant as the build engine, and the IDE generates the Ant script automatically. I’m not going to go into much detail concerning what you can do with custom build steps – I suggest you read the well-commented Ant scripts, and look at this section of the NetBeans documentation.

There are standard stages in the build process where we can add tasks (’targets’ in Ant-speak) to the NetBeans build. The build.xml file (in the project root) contains a comment describing these. All we want NetBeans to do is copy the logback.xml file into the dist folder after it has finished building the jar file, so we will add a -post-jar target to copy the file:

<target name=”-post-jar” >
<copy file=”${src.dir}/logback.xml” todir=”${dist.dir}”/>
</target>

Add this target at the end of build.xml, just before the close-tag for . Now rebuild the project, and take a look in the dist directory: you should see that logback.xml has been copied there. Now you’re ready to zip the dist folder and distribute your solution.

That’s the end of this little piece. You should know enough now to add straightforward, high-performance logging to your own projects. But there’s a lot more to learn: to go further, study the slf4j and logback documentation, follow the examples, and experiment.

While looking around for Java dependency tools I came across KirkK’s site, and his JarAnalyzer.  As usual, I wanted to know a little more about the person behind the software, so looked up his blog and found an article from 2007 there which really resonated with me: .Net : Software & Technology @kirkk.com

Kirk and I have travelled in opposite directions: he crossed the tracks to work on a .NET project, whilst I’ve recently shifted my attention almost completely from .NET and the Microsoft environment (where I have spent the last 10 or so years) to the world of Java.  What’s interesting is that he so quickly formed the same view of the Microsoft development that motivated my move to Java.

Microsoft’s greedy behaviour has done so much damage to its reputation and the level of goodwill amongst independent developers. Kirk cites the example of TestDriven.Net, but there are examples of other ‘alt.net’ type projects (NAnt and NDoc, for example) which Microsoft has effectively (though not directly) either killed or marginalised, not with licensing terms but by introducing proprietary (and arguably weaker) competing technologies.  I’m sure that part of the reason for that, with the N-prefixed projects at least, was that they couldn’t bear the prospect of absorbing something with what they would see as alien DNA into their product line.

This piece by Mike Hofer describes the NDoc demise and nicely summarises the twin underlying problems: the nature of the development community surrounding the Microsoft platform, and Microsoft’s inability (or unpreparedness) to work with it. Mike’s article, and the linked post by Charles Chen containing the email from NDoc’s founder, make for quite depressing reading. Perhaps the emergence of a mean-spirited, mean-minded community is to be expected, when the centre of its universe is an avaricious commercial juggernaut?

I feel these things especially keenly, now that I’m looking over the wall from the Java community side.  The contrast really couldn’t be more stark, more impressive and more compelling.  Even the large companies operating in this space, notably Sun Micrososystems, appear intelligent, enlightened and innovative; there’s a very healthy culture here. (A quick and revealing experiment: take Microsoft and Sun – now try to find the corresponding CEO’s blog. Top hit in Google for Steve Ballmer when I tried was a send-up site; top hit in Google for Jonathan Schwartz was Jonathan Schwartz’s blog. And it’s worth reading).

Coming back to the issue of building a healthy community around a technology, Sun’s Java is surely the shining example of how to embrace the great work done by independent developers and build on it, rather than trying to crush it. Just look at NetBeans: this is an enterprise-quality IDE, easily the equal of Visual Studio, but not only is it open-source (and free to download) it also employs established open-source tools instead of imposing inferior alternatives: For unit testing, JUnit is completely integrated; NetBeans uses Apache Ant as its underlying build-system; it can work seamlessly with Maven through the excellent plugin. And you choose the version-control system you prefer (e.g. Mercurial, Subversion) and NetBeans will allow you to make full use of it, right inside the IDE.

Lastly, you are free to extend NetBeans by writing whatever plugins (modules) you please, without running the risk of getting into litigious exchanges like the TestDriven.Net debacle described here, which seems to me to plumb the very depths of time-wasting pointlessness.

I never intended to write all that: it was originally just a reaction to a (rather old) blog entry. But as I revisited the world of the Microsoft monoculture through the tale of those N-projects, it just tumbled out.