Saturday, 29 November 2008

Brunel, Robert Howlett and David White

Just came across this wonderful short piece on the BBC website. Well worth watching. What a great idea: well done to David White and the BBC.

Modern-day civil-engineering rarely seems to aspire to match that mixture of functional beauty and sense of proportion which Brunel's works all seem to have. But I must put in a good word for the revived, extended and transformed St. Pancras International station. The main concourse is a marvellous place to be (apart from the silly, cheesy, oversized statue of the couple): a couple of times recently, when on our way back to King's Cross station, Dan and I have walked in just to take-in and admire what's been done.

Then we wander back to the dirty, grim, gloomy shed which is the current King's Cross. We've often talked about how wonderful it would be if something similar to St. Pancras were done for King's Cross. The good news is that Network Rail is working on it.

Friday, 28 November 2008

Logging in NetBeans using slf4j

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.

Thursday, 20 November 2008

Leonard Cohen at the Albert Hall!

On Tuesday my wife and I were finally able to use her (rather belated) birthday present from me - tickets for Leonard Cohen.  At the Albert Hall!  It was spectacularly good - great seats (stalls, so good line of sight over the arena floor), amazing sound quality, and of course the Man himself, a living legend, who delivered an astonishing 3 or more hours of the finest entertainment I can recall.  The band were superb: every member individually talented but, as with all the best ensembles, the whole was even greater than the sum of the parts. I can't recall a better evening.

But it so nearly didn't happen, for us ...  I had originally bought tickets on eBay, the only place I had been able to find really good seats for the London concerts so-far announced, which were at the O2 Arena.  Not a venue we fancied much, but at the time I don't think the Albert Hall dates had been arranged.  The O2 tickets were in the first couple of rows right in front of the stage, so we were pretty pleased with ourselves. I paid, and waited.

And waited ... and chased the seller, again and again.  Who turned out not to have the tickets at all, but was "expecting to receive them from the promoter" shortly before the date.  Lots of promises about keeping us informed, lots of reassurances they would arrive in time. Until eventually, two days before the gig, I receive an email from the seller saying that some tickets have arrived but are for the wrong event!  By now we're way past the eBay 90-day limit for disputes. Moral: do not trust individuals selling concert tickets on eBay. If you do go ahead, demand the tickets or your money back well within eBay's limit.

Fortunately, I found an online ticket company (Double8tickets) with the AH seats, via a Google ad which appeared in GMail! Normally, I ignore these ads, but this one leapt out at me at a time when I was desperate to find tickets, so I wouldn't have to disappoint Chris.  Just goes to show that these unobtrusive little ads can work very effectively, and are so much less irritating than the loud, flashy mess that flickers away above Microsoft's Live or Hotmail frame.


Friday, 14 November 2008

Community and Culture

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.

The Managerese Disease

I recently stumbled upon a wonderful collection of that language we all love to hate: managerese.  Kevin Boone's list is here:

The K-Zone: New developments in managerese

There are other lists like this sprinkled around the net, but this one is the best I've seen so far because it manages to combine a bit of thoughtful deconstruction with some satisfying disdain.