Monday, 22 November 2010

Logging Do's and Dont's

Inspired by this post on The Dark Art of Logging I thought I'd add a few logging do's and dont's of my own.

DO Use SLF4J

SLF4J is a very thin interface for logging, with multiple different actual logging backends supported - particularly log4j, java.util.logging and logback. You can add your own logging backend very easily indeed, or add an adaptor to an existing logging system such as log5j. It follows a similar API to log4j/commons-logging.

If you are writing a library you should be using it because it means you aren't dictating a logging backend to your clients - they can use whatever they like. If you are writing an application you should use it to insulate yourself from future change - you can switch from log4j to logback to java.util.logging to some other logging backend as yet unwritten at will without making code changes.

This is a very brief argument for SLF4J - there are more in depth ones referenced here.

DO Use SLF4J's Parameterized Logging

Traditionally debug logging statements involving expensive string concatenation are wrapped in a check to save the expense of generating the message when the log is disabled:

if (log.isDebugEnabled()) {
    log.debug("created user[" + user + "] with role [" + role + "]");
}

With SLF4J you don't need to use this rather noisy format and can get the same performance characteristics using parameterized logging:

log.debug("created user[{}] with role [{}]", user, role);

DO Log the Exception Stacktrace

This is really important. Far too often you see code like this:

try { ... } catch (Exception e) {
    log.error("Something went wrong: " + e); // DON'T DO THIS - LOGS THE EXCEPTION'S TOSTRING, NOT THE ENTIRE STACKTRACE
}
By only concatenating in the exception's toString two pieces of vital information have been lost here; the stacktrace, which tells you where the problem happened, but as importantly the cause. It is quite common to have exceptions caused by other exceptions in a chain three or more deep; and irritatingly the toString of an exception does not contain the toString of its cause. Very often the cause was something the developer did not anticipate at all, and so without that information you are at a huge disadvantage when exploring a problem. When logging an exception ALWAYS do this:
try { ... } catch (Exception e) {
    log.error("Something went wrong", e);
}
Another anti-pattern when using log4j directly is this:
private static final Logger log = org.apache.log4j.Logger.getLogger(Object.class);
try { ... } catch (Exception e) {
    log.error(e); // DON'T DO THIS - LOGS THE EXCEPTION'S TOSTRING, NOT THE ENTIRE STACKTRACE
}
You can call log4j like this because it accepts Objects and calls toString on them rather than accepting Strings, but the net effect is that you have once again discarded the stacktrace and the cause of the exception, probably accidentally. This is another good reason for using SLF4J - the code above just won't compile because the message has to be a String in SLF4J.

A good logging backend will allow you to discard the stacktrace as part of the logging config, just like you can discard entire messages based on their level or logger, so this isn't forcing you to pollute your logs with endless stacktraces - it just means that when you have an issue you can get the stacktrace just by changing logging config, without needing to change code, repackage and redeploy.

DO Chain Exceptions

If you should always log the exception in order to get its cause, it follows that when catching a low level exception and throwing a higher level exception you should always pass the low level exception as a cause to the high level exception. Never do this:

try { ... } catch (Exception lowLevelException) {
    throw new HighLevelException("Something went wrong doing the work"); // DON'T DO THIS - NO CAUSE!
}
Instead do this:
try { ... } catch (Exception lowLevelException) {
    throw new HighLevelException("Something went wrong doing the work", lowLevelException);
}

DON'T Log Exceptions Before You Handle Them / DO Log Exceptions When You Handle Them

This might be controversial, but I am strongly of the opinion that you should never have code like this:


public static void rootMethod() {
    try {
        doHighLevelWork();
    } catch (HighLevelException highLevelException) {
        log.error("exception trying to do z", highLevelException);
        // recover
    }
}

public static void doHighLevelWork() throws LowestLevelException {
    try {
        doLowLevelWork();
    } catch (LowLevelException lowLevelException) {
        log.error("high level work went wrong because of y", lowLevelException);
        throw new HighLevelException("high level work went wrong because of y", lowLevelException);
    }
}

public static void doLowLevelWork() throws LowestLevelException {
    if ( /* something goes wrong */ ) {
        LowLevelException lowLevelException = new LowLevelException("it went wrong");
        log.error("low level work went wrong because of x", lowLevelException);
        throw lowLevelException;
    }
}

public abstract class BaseException extends Exception {
    public BaseException(String message, Throwable cause) {
        super(message, cause);
        log.error("An exception happened", this);
    }
}
public class LowLevelException extends BaseException { ... }
public class HighLevelException extends BaseException { ... }
By the time the root method actually recovers, we've logged the same low level exception as error five times! And all of the information was logged by the last log.error call in the root method.

You should log an exception once and only once, otherwise when examining a log file for stacktraces you are confused by the same data replicated multiple times, which obfuscates the actual cause and quantity of problems. That leaves us with the problem of when it is you should log it. I am strongly of the opinion that you should leave it to clients of your code to log your exception as they see fit at the point where they actually handle it (so not when re-throwing it as the cause of a higher level exception). You don't know how serious clients think an exception is when you throw that exception. Let them decide what to do with it, including logging it.

So what about the extra contextual information you were logging at each level? Add it to the exception itself, ensuring that it will be printed in the exception's message and also be available programatically to your clients. Then when it is logged with stacktrace out will come all that contextual information, just as you need it.

DO Log Uncaught Exceptions

If you're going to follow the advice above then obviously it's vital that exception does get logged at some point, so make sure your application logs uncaught exceptions when it handles them. The default behaviour of a standalone Java app is to call exception.printStackTrace(); you can override this as follows:

Thread.setDefaultUncaughtExceptionHandler(new Thread.UncaughtExceptionHandler() {
    @Override
    public void uncaughtException(Thread thread, Throwable e) {
        Logger log = LoggerFactory.getLogger(thread.getClass());
        log.error("Exception in thread [" + thread.getName() + "]", e);
    }
});
In a webapp you can send the uncaught exception to a jsp page, where you have full control and can log it:

  java.lang.Exception
  /error.jsp

In Spring you can setup exception resolvers.

DO Use Aspect Oriented Programming for Trace Logging

If you're writing code like this:

public String doSomeWork(String param1, Integer param2) {
    log.trace("> doSomeWork[param1={}, param2={}]", param1, param2);
    String result = /* work done here */;
    log.trace("< doSomeWork[{}]", result);
    return result;
}
in every method then it's time to find out about Aspect Oriented Programming. You can use something like AspectJ to add the trace statements to all methods at compile time, resulting in bytecode that contains the trace calls, or you can use instrumentation to add them to the loaded class at runtime. You could even use Groovy AST transformations or Spring proxies, though the latter will only add trace logging to calls between objects. I'll try and blog about these further in future, but the net result is you still get your trace logging but your method now looks like this:
public String doSomeWork(String param1, Integer param2) {
    String result = /* work done here */;
    return result;
}

DON'T Pass Sensitive Data Around as Strings

A corollary of using aspect based trace logging is that there is a grave danger of logging sensitive information. Consider the following method:

public String login(String username, String password) {
    String token = ...;
    return token;
}
Apply a trace aspect to this and you can turn on output like this:
TRACE > login[username=MYUSERNAME,password=abc123]
TRACE < login[sensitivesessiontoken]
Less than ideal from a security perspective!

If you follow good Object Oriented practices and wrap these values in small classes, you can make the toString method return an obfuscated value in production environments and an unobfuscated one in development environments, protecting you from any accidental output from toString methods:

class Password {
    private String passwordValue;
    ...
    public String toString() {
        if (env == PROD) {
            return "[password concealed]";
        } else {
            return passwordValue;
        }
    }
}

class Token {
    private String tokenValue;
    ...
    public String toString() {
        if (env == PROD) {
            return partiallyObfuscate(tokenValue);
        } else {
            return tokenValue;
        }
    }
}

public Token login(Username username, Password password) {
    Token token = ...;
    return token;
}
Now your log output is rather less insecure:
INFO > login[username=MYUSERNAME,password=[password concealed]]
INFO < login[...itivesessiont...]

Monday, 11 October 2010

Which Java Thread is using CPU on Linux?

More for my own reference than anything else, a means to establish which java thread is using CPU time on Linux.

  1. Get the process ID (PID) using ps -ef
  2. Enter the command
    top -p<pid>
  3. Press shift-h
  4. All threads in the parent java process should start to appear with their lightweight process IDs and CPU usage - this takes some time
  5. Now send a
    kill -3 <pid>
    to the process - this will trigger a thread dump without ending the process.
    CTL-\
    will also work if you have java running in a console.
  6. Convert the PIDs of the lightweight process you are interested in into hex (so 2042 = 0x7FA)
  7. Find the file where the Java process was sending system.out and grep for
    nid=<lightweight pid in hex>
Bingo, you should have the thread name and stack of the thread using up CPU time

Wednesday, 29 September 2010

We Need More Language Choice in the Browser

If you're a server-side developer, you have an enormous amount of freedom. You can write your code in Java, C++ JavaScript, Groovy, Scala, Ruby, Python, php, C# and probably a thousand other languages; fundamentally a web server will run as a stand-alone programme on hardware, and so as long as there's a compiler (or a virtual machine in the case of managed code) for your hardware you are good to go. You may get more or less help from libraries and frameworks, but in the end you are reading a stream of data from a socket and writing a stream of data back, and it's an odd language that can't do that.

But the server side is dead. OK, that's a ridiculously massive exaggeration - being sensible, clients are getting thicker and consequently servers are getting thinner. And clients are getting thicker because of the increasing power of browsers and the understanding that it's a lot simpler to handle client state in the client than to manage it by passing it back and forth to the server in multiple requests. Ajax, Web 2.0, Web Sockets, HTML5 - increasingly the web is about delivering a thick client to the browser that then only does server-side communication when it actually needs to get data or persist data in a form that is non-local.

All of which is lovely, but it's moved us from a world of massive choice when creating business logic to a world of very little choice. Because browsers don't run machine code, they run JavaScript, JavaScript and only JavaScript (unless you want to lock yourself into Microsoft's cosy little ecosystem).

Now I'm not saying JavaScript/ECMAScript is a bad thing. I suspect some notable people think it is the Next Big Language. I'm sure you can write powerful, elegant and beautifully factored code in it.

However, the joy of languages that run outside the browser is that if you disagree with the way a language does things you can use a different one you prefer. You don't need to have religious wars about it, there doesn't need to be a One True Language To Rule Them All - you want to hack in Delphi, off you go and hack in Delphi. That was why Apple's decision to limit the languages in which you can develop for the iPhone was so wrong. (You want to be employed by someone else to write their code for them and you'll have to do it their way, but that's life as an employee.)

We don't have that freedom on the browser. The browser doesn't even read compiled code, it only reads source files. There are work-arounds, of course; you can use GWT or XMLVM or something similar to compile Java (or Groovy or Scala...) to JavaScript. But this is not first class support for another language; it's highly dependent on third party tools that may or may not see much support (the XMLVM JavaScript output is no longer under development).

What I would like is if browsers could interpret JVM bytecode, not in an obscure Japanese framework that seems to have died, but natively in the browser with the browser having the common runtime classes so they don't have to be provided in every case. Then we could at least use Java, Groovy, Scala, Jython, JRugby, Clojure and others to write our client side code. Of course that's still a very JVM centric view of the world; I'm not really sure how you could do this with languages like C and C++ that compile directly to machine code and expect to manage memory themselves, but you could certainly imagine doing it for the CLR byte code and so make all .net languages available (IE probably does this, for all I know).

There are challenges, of course; JavaScript as run in the browser is a single event listening thread which cannot do I/O, so the available libraries would be pretty limited and there would be a lot of standard runtime classes and packages unavailable, just as they are in GWT. But it would be good to be freed up again to allow developers to choose the language they prefer.

(Am I revealing my lack of knowledge of Applets here? I think of them as virtually stand-alone applications, rather than natively working with the browser events, XMLHttpResponses and the structure of the DOM, but I've never really used them in anger - I sort of assume that since GWT isn't applet based they don't give you what I'm talking about, but I guess it's possible that Google decided to go the GWT path to avoid needing the Java plugin on the browser...)

Monday, 20 September 2010

Synthetic Composite Types with Java Generics

Perhaps everyone already knows about this, but I just found a very interesting feature of Java Generics - you can declare synthetic composite types using multiple bounds to allow you to treat two different classes that implement the same interfaces as if they had a common super type, even if they don't.

Consider the following classes:

interface FooInterface {
    void methodOnFooInterface();
}
interface BarInterface {
    void methodOnBarInterface();
}
class Foo implements FooInterface, BarInterface { ... }
class Bar implements FooInterface, BarInterface { ... }

Now imagine that you want to write a method that depends on taking items that are both FooInterface and BarInterface, but beyond that does not care about their types. It should accept both instances of Foo and Bar. In the past I'd have cursed the fact that Foo and Bar have no common supertype capturing being both FooInterface and BarInterface, but I now know you can declare a method as so:

<T extends FooInterface & BarInterface> void doSomething(T instance) {
    instance.methodOnFooInterface();
    instance.methodOnBarInterface();
}
doSomething(new Foo());
doSomething(new Bar());

However, what I haven't yet worked out how to do is use a method that can take a Collection of that synthetic type, as so:

<T extends FooInterface & BarInterface> void doSomethingElse(Collection<T> collection) {
    for (T instance : collection) {
        instance.methodOnFooInterface();
        instance.methodOnBarInterface();
    }
}

The method declaration works, but how to call it? I can find no way to instantiate a Collection with a synthetic type - this does not work:

Collection<FooInterface & BarInterface> things = new ArrayList<FooInterface & BarInterface>); // DOES NOT COMPILE
this.add(new Foo());
this.add(new Bar());
doSomethingElse(things);

Can anyone help? This feels to me like a very powerful feature, potentially.

Edit: found a clunky way to do it:

<T extends FooInterface & BarInterface> Collection<T> makeCollection(T instance1, T instance2) {
    Collection<T> collection = new ArrayList<T>();
    collection.add(instance1);
    collection.add(instance2);
    return collection;
}
doSomethingElse(makeCollection(new Foo(), new Bar()));

It would look more flexible with varargs, but then the compiler issues a warning about unchecked operations; a warning isn't the end of the world so that may be a preferable solution. But it's still pretty ugly - you cannot pull the

makeCollection
call out into an instance variable as there is no way to declare its type, so it has to stay inlined.

Thursday, 16 September 2010

Release of sysout-over-slf4j version 1.0.0

I'm pleased to announce the release of sysout-over-slf4j version 1.0.0, a bridge between System.out/err and SLF4J.

This effectively translates a call such as:

class Foo {
 ...
    System.out.println("Hello World");
 ...
}

into the equivalent of:

class Foo {
 ...
    LoggerFactory.getLogger(Foo.class).info("Hello World");
 ...
}

allowing automatic generation of logging information such as timestamp and filtering of statements using any SLF4J implementation such as Log4J or Logback.

The project page is here:

http://projects.lidalia.org.uk/sysout-over-slf4j/

The artifacts can be downloaded here:

http://github.com/Mahoney/sysout-over-slf4j/downloads

Or via the Maven central repository:

<dependency>
    <groupId>uk.org.lidalia</groupId>
    <artifactId>sysout-over-slf4j</artifactId>
    <version>1.0.0</version>
</dependency>

Sunday, 13 June 2010

Scala Frustrations

I'm learning Scala at the moment. I went looking for other "Java++" type languages after programming in Groovy for some time, and was very hopeful that Scala was what I was looking for - a type safe fully object based Java-like language, with clever stuff to save you typing the types. And there are lots of bits of it I really like - the var/val way of specifying whether a variable is final is nice, the object concept that allows you to have singletons that implement interfaces/traits, the removal of operators in favour of allowing them as method names. All good.

However, I'm finding it frustrating. One of the things Scala claims is that it has fewer special cases than Java; notably it has no primitives and no operators. Yet I keep on coming up against some pretty fundamental, and to me highly surprising, special cases.

First there's the whole notion that if you name a method ending in :, and you want to call it in operator notation (instance methodname argument rather than instance.methodname(argument)) then you call it by placing it to the left of the object on which you are calling it - so argument methodname: instance. To me that's a humungous special case. At the moment it seems to me that it's been added solely in order to make prepending to Lists more natural, because Scala lists are immutable and so the time taken to append apparently grows linearly whereas the time taken to prepend is constant. I can't help but feel that's an insufficient reason to introduce a massive syntax divergence from the norm. Is there really no other way? Would an immutable List backed by a mutable LinkedList (so appending returns a new view over the same List) really perform so badly when appending? And if it does, could it not be just a case where developers need to be cautious, as with String concatenation in Java?

Then there's the operator precedence rules. Scala doesn't have operators, right? Only methods? Wrong. It has a few method names which are special cased to have a different precedence order because they are normally operators in other languages. Nice. So for instance (2 + 2 * 5) == 12, whereas ((2).+(2).*(5)) == 20, despite the fact that they are the same methods in the same order on the same objects - Scala just specifies that 2 + 2 * 5 is treated as 2 + (2 * 5). I understand this one, I'm sure it's to align Scala with mathematical convention, but I still disagree. Having a bunch of methods who behave differently in terms of order of evaluation to others based on their name is a huge and confusing special case.

Then there's the Tuple behaviour. You can declare a tuple as so:

val aTuple = (12, "astring")

but if you want to reference the first element, it's one index based! aTuple._1 == 12, aTuple._2 == "astring". I find this staggering - the whole of the rest of Scala, as a descendant of C/C++/Java, is 0 index based. Apparently it's becase Haskell uses 1 index base for its tuples, but surely this is a case where you should ignore Haskell's arbitrary conventions and be internally consistent. Hands up anyone caught out by JDBC's one index based behaviour?

Then there's the behaviour of + and += on mutable and immutable Maps and Sets. On an immutable Map +(Tuple) returns a new Map instance with the Tuple added, as you'd expect. If you call += it attempts to assign the resulting new Map instance to the variable, also as you'd expect - so

val aMap = Map(1 -> "one")
aMap += (2 -> "two") // cannot compile - reassigning aMap to a new instance

will fail to compile, because you are trying to reassign aMap. So far, so good

On a mutable Map the behaviour of +(Tuple) is consistent - it returns a new Map instance with the new entry, it does not mutate the original one. Again, good. However, the behaviour of += is completely inconsistent - it mutates the map on which it is called, but does not reassign the variable! So

val aMap = scala.collection.Map( -> "one")
aMap += (2 -> "two") // compiles!

does compile - it isn't reassigning the aMap variable, just mutating the underlying instance. To me that's crazy; += screams "variable reassignment", it does not scream "mutate this instance, keep same assignment". I'd be happy if the + method mutated a mutable instance and returned a new instance on an immutable type, or alternatively if it was absolutely consistent and the + method always returned a new instance leaving the instance on which it was called unaltered and some other method (Groovy uses <<) were responsible for mutating - but either way, the += operation should do exactly the same as the + operation with the caveat that it reassigns the variable to the result of the operation. It should not, in my opinion, ever be possible to call += on an instance stored in a val declared, and hence final, variable. The same confusing behaviour can be observed on Sets.


It's true that I'm very new to Scala, and in some ways this blog post is injudicious - perhaps if I stick with Scala in a year or two I'll look back and be baffled by my lack of understanding and folly in speaking up knowing so little. But so far I'm finding this sort of thing significantly reducing my enthusiasm for going further.

Injecting a bean into a Grails Controller without using auto-wiring

Imagine a nice simple Grails app - Foo1Controller and Foo2Controller both have a BarService property, auto injected by name as Grails likes to do.

package foo

class Foo1Controller {

  BarService barService


  def anAction = {
    barService.doSomething()

  }

}

package foo
class Foo2Controller {

  BarService barService


  def anotherAction = {

    barService.doSomething()

  }

}

BarService {

  void doSomeThing() {

    // do something

  }

}


All is well, until we find that actually we need two different implementations of BarService, and the two controllers must each use a different one.

The initial refactor of the service is simple:

interface BarService {
  void doSomething()

}




class Bar1Service implements BarService {

  void doSomeThing() {

    // do something
  }
}

class Bar2Service implements BarService {
  void doSomeThing() {
    // do something else
  }
}

Grails uses Spring, right?  So we can just choose to inject the right one into the right controller!  Problem is that Grails likes to auto-wire its controllers by name (or by type if you prefer).  Not so hot for a configuration & server restart based change in implementation.  You're going to have to alter the source code to persuade Grails to wire Bar1Service into Foo1Controller and Bar2Service into Foo2Controller.

Well, turns out you can just do it in resources.groovy as so:

barService(Bar1Service) { bean ->
  bean.autowire = 'byName'
}

'foo.Foo2Controller'(Foo2Controller) { bean ->
  bean.scope = 'prototype'
  bean.autowire = 'byName'
  barService = ref(ConfigurationHolder.config.foo2.barservice)
}

Config.groovy:

foo2.barservice = 'bar2Service' // valid values are barService and bar2Service

Now, so long as your config is loaded from outside the war file, you can switch the implementation of BarService for Foo2Controller in config, restart and all is good - no need for a redeploy.

Interesting points:

  • By declaring Bar1Service with a name of barService in resources.groovy, we still got all the benefits of it being auto-wired into any controller (such as Foo1Controller) that declares a barService without needing to declare that controller in resources.groovy
  • By using bean.autowire = 'byName' in all the bean declarations we got the default Grails wiring for all other properties
  • When declaring the Controller in order to choose the BarService implementation we needed the full name - package.ClassName - as the bean name
  • When declaring the Controller we needed to give it a scope of prototype - to ensure we get a new instance of the Controller each time

One other thing - we're stuck on Grails 1.1.1.  So no guarantees this works with the latest version - though we are about to upgrade, so hopefully I'll be able to edit this post and remove this caveat soon.

Wednesday, 21 April 2010

Accessing Jetty on Ubuntu from another machine

OK, so following on from my previous blog post I thought I'd do some performance testing to see how Jetty compares with Apache. Installed VirtualBox on my Mac, downloaded and installed ubuntu 9.04 server edition with bridge networking so I could access it from the host - all painless. Installed apache2 - painless. Installed jmeter on the mac - painless. Ran some performance tests.

Looked to repeat the experiment against Jetty - aargh!! Just wasted 3 hours trying to work out why I couldn't connect to Jetty from the host. Turns out that the documentation, in Debian/Ubuntu at least, is wrong - when /etc/init.d/jetty claims that leaving JETTY_HOST blank will result in accepting connections from all hosts it's lying. You need to set it to 0.0.0.0 or it will only be accessible from localhost (127.0.0.1). You can tell this because if you do a netstat -an you will see this:


Proto Local Address State
tcp6 0 0 127.0.0.1:8080 :::* LISTEN


that means the bind-address is localhost so the process is inaccessible outside the server. It should look like this:


Proto Local Address Foreign Address State
tcp6 0 0 :::8080 :::* LISTEN


Hope this helps some other poor confused person out there, took me a long time to Google this... there's a Debian issue here:
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=554874

Monday, 19 April 2010

Web Application Architecture - do I really need Apache?

Following on from my earlier post on web application architecture, there's another aspect of the common pattern I'm curious about - do I really need Apache?


I had a frustrating time recently performance tuning an application. This was partly because we were shooting at a moving target (performance test servers on a shared virtual environment where resources may be claimed by another server at any moment are not a great idea...), and partly because I still need to improve my knowledge of Apache, Jetty, Linux and performance tuning methodologies. However, I did feel that having Apache in the mix added an extra layer of variables, measurement and configuration complexity; matching available sockets/open files on the operating system to numbers of apache workers to numbers of Jetty connections, bearing in mind cache hits and misses at the Apache level, all got quite complicated.

It made me question why we need Apache. It serves three purposes in our architecture.
  1. Block external access to certain URLs
  2. Put in place redirects when we, or systems we depend on, have problems
  3. Act as our HTTP cache
1 & 2 we could easily do via filters at the application server layer - indeed we're moving that way anyway, as it's then trivial to implement admin pages to toggle these settings and it's also considerably easier to functionally test them.

Which leaves the HTTP cache. I've been reading up on my HTTP caching recently, particularly in an excellent book called "High Performance Web Sites". It got me thinking, and it seemed to me that it wouldn't be that hard to implement an internal HTTP cache in a servlet filter. A quick google revealed that unsurprisingly I wasn't the first to think of this, it being the subject of an O'Reilly article, and indeed that Ehcache have something along those lines.

The advantages I see to using such a cache are fivefold:
  1. You get the reduced complexity of taking a layer out of your architecture. You no longer need to worry about how many connections & threads both Apache and the application server need - there's just the one to get right.
  2. You get to escape from Apache's rather arcane configuration (or is it just me who winces in distaste whenever delving into httpd.conf?)
  3. You can easily get a distributed cache. Astonishingly Apache doesn't seem to have an off-the-shelf distributed implementation of mod_cache, which has been an issue for us - we have requests for pretty rapidly changing data which we really need to cache for short periods of time to protect ourselves from a user perpetually refreshing
  4. The cache will be shared across all threads in the application server, regardless of what form you choose to store it. Did you know that mod_mem_cache is a per process cache if you run Apache on a process-per-request basis (as RedHat does out of the box)? So loading up the cache for a resource has to be done on every single process - and what's worse, by default those processes are configured to die when idle or after a set period of time even if not idle to avoid a memory leak. So that resource you thought was being cached eternally is actually getting requested rather a lot. Apache recommend using mod_disk_cache instead, where the cache is shared across all processes, and relying on the operating system to cache it in memory to speed things up, but my measurements saw a drastic drop off in performance when we tested this. I may of course simply have got something wrong.
  5. A personal one - as a Java dev I'm a lot happier digging into Ehcache's codebase to work out what it's actually up to than I would be in Apache's.
It would be quite reasonable to read that list and snort that perhaps I need to improve my Apache skills - and perhaps that is indeed the case. However there's a level at which that's my point; if I need to read up and gain painful experience in order to know how to bend Apache to my will and really know what it's up to, isn't it reasonable to look for an alternative that I will understand better and faster?

So what are the negatives? Well, I've seen it suggested that Apache, being native code, is faster at shoving binary data to a socket than a JVM is. On the same basis I guess that if you are using a disk based store for your cache Apache may be more efficient at reading data from the disk. I've no proof for either of those theories, though, and it may equally be that modern JVMs are pretty competitive at these things - you'd think they'd be the sort of thing Sun had been optimising like crazy all these years. More reading and/or testing needed.

On I presume the same basis Apache has a reputation for serving static content much faster than an application server (this doesn't really apply to my current project as we use JAWR for much needed efficiency savings, and that means the application server has to serve our static content up the first time; hopefully thereafter it's being served from a cache anyway). I seem to remember being told, however, that modern servlet containers are actually quite competitive on this score now (a good wikipedian would add a nasty little [citation needed] or [where?] to that sentence!).

There may also I guess be security issues with running a servlet container or application server on port 80; Apache has had the benefit of being the market leader and hence the target of so many hackers that you'd hope most of the holes have been stopped up. Though there may be an element of the safety of obscurity by stepping away from Apache.

I'd certainly be interested in experimenting with dropping Apache, running the servlet container on port 80 and using Ehcache or similar to do caching & gzipping down at the Java layer. Perhaps if I do I will find out why no-one else does!

Web Application Architecture - why so many nodes?

I've been thinking recently about the standard architectures we have for Java based web applications. Obviously these do vary, but in my experience they have some pretty common patterns:
  1. Two identical legs (staging and production) that switch on each release
  2. A couple of load balancers on each leg (one for fail over)
  3. Multiple nodes behind these (more than 4 on a relatively high volume website)
  4. Each node having a web server running Apache httpd 2.x, responsible for HTTP caching and possibly serving up static content when it isn't already cached
  5. Each node also having an application server running a servlet container or J2EE application server
  6. A database, typically with at least a couple of nodes for failover reasons
There are other issues, of course, such as how you manage sessions, but they aren't what concerns me at the moment. I'm interested in questioning (from a position admittedly of some ignorance...) an aspects of this pattern.

The first is the rationale for having more than two nodes. On my current project we have four, about to become six. However, we are also deploying into a virtual environment - VMWare based, where you add resources like memory and CPUs via a console. In those circumstances I'm not entirely clear why the response to higher load should be more nodes. Why not simply increase the resources available to each virtual machine? Particularly in a 64bit, multiprocessor age, surely the operating system and JVM can scale up to use the extra resources as they are presented?

I'm partly standing here to be corrected - I'd love to be educated as to why this assumption of mine is naive and wrong! Do sockets and open files still represent a bottleneck in an up-to-date Linux server? Is there just a point of diminishing returns where throwing more CPUs and more memory at a single operating system & JVM combination doesn't scale anywhere like linearly?

I ask simply because otherwise having more than two nodes (obviously I understand you need two for failover) seems to add a lot of complexity if it's not actually giving benefits to match. The more servers there are the more maintenance there is, the longer deployments take, the more you are likely to play hunt-the-log-message from server to server to follow a user's behaviour... you know the deal.

Now in typing that I have to acknowledge another clearly good reason to have more than two nodes - lose one out of two and the traffic going to the other just leapt by 100% at a time when you may well be experiencing pretty high traffic if one of your nodes has gone down. One out of four goes down and the others only have to cope with a 33% jump in traffic. But I'd still be interested to know if that's the sole reason for it, or if there's a scalability issue I need to read up on. Any book suggestions on the topic?

System Out over SLF4J Code Complete

I've just completed a new SLF4J legacy bridging module - sysout-over-slf4j. I've donated it to SLF4J, so I'm hopeful it will soon be available as a binary there and hence in the Maven repositories. However, in the meantime anyone interested can pull it down from my github fork; it's a simple Maven project, a quick mvn package in the root of sysout-over-slf4j should do the trick. If you're interested you could add comments here or on the bugzilla enhancement request

The basic idea is to transform real old school System.out.println("log message") and exception.printStacktrace() into modern logging statements that can be managed by log4j or logback or any other logging system that implements SLF4J or has a conversion layer from it, using the now standard convention of logging to a logger whose name is the same as the fully qualified name of the class doing the logging. Here's the documentation:

System.out and err over SLF4J

The sysout-over-slf4j module allows a user to redirect all calls to System.out and System.err to an SLF4J defined logger with the name of the fully qualified class in which the System.out.println (or similar) call was made, at configurable levels.

What are the intended use cases?

The sysout-over-slf4j module is for cases where your legacy codebase, or a third party module you use, prints directly to the console and you would like to get the benefits of a proper logging framework, with automatic capture of information like timestamp and the ability to filter which messages you are interested in seeing and control where they are sent.

The sysout-over-slf4j module is explicitly not intended to encourage the use of System.out or System.err for logging purposes. There is a significant performance overhead attached to its use, and as such it should be considered a stop-gap for your own code until you can alter it to use SLF4J directly, or a work-around for poorly behaving third party modules.

What needs to be done to make it work?

sysout-over-slf4j.jar should be included on the classpath at the same level as slf4j-api.jar and your chosen slf4j implementation. A static method call sendSystemOutAndErrToSLF4J() should be made on the org.slf4j.sysoutslf4j.context.SysOutOverSLF4J class early in the life of the application to start redirecting calls to SLF4J, or the included org.slf4j.sysoutslf4j.context.SysOutOverSLF4JServletContextListener may be configured in a servlet application.

How does it work?

The System.out and System.err PrintStreams are replaced with new SLF4JPrintStreams. Each time a call to System.out.println (or similar) is made, the current thread's stacktrace is examined to determine which class made the call. An SLF4J Logger named after that class's fully qualified name is retrieved and the message logged at the configured level on that logger (by default info for System.out calls and error for System.err calls).

Calls to Throwable.printStackTrace() are likewise logged at the configured level for each System output. By default there will be a message logged for every line of the stack trace; this is an unfortunate side effect of not being able reliably to retrieve the original exception that is being printed.

A servlet container may contain multiple web applications. If it has child first class loading and these applications package SLF4J in the web-app/lib directory then there will be multiple SLF4J instances running in the JVM. However, there is only one System.out and one System.err for the whole JVM. In order to ensure that the correct SLF4J instance is used for the correct web application, inside the new PrintStreams SLF4J instances are mapped against the context class loader to ensure that the same SLF4J instance used in "normal" logging is also used when calling System.out.println.

In order to prevent classloader leaks when contextsare reloaded the new PrintStreams are created by a special classloader so that they do not themselves maintain a reference to the context classloader. However, since the PrintStreams do maintain a reference to the context's SLF4J instance the user must also stop sending System.out/err to SLF4J in a context before discarding or reloading it to avoid a classloader leak via the stopSendingSystemOutAndErrToSLF4J method on the SysOutOverSLF4J class. This happens automatically if using the provided SysOutOverSLF4JServletContextListener.

Don't most logging systems print to the console? Won't that mean infinite recursion?

Fortunately, Log4J, JULI & Logback all do so through the write methods on PrintStream, which are rarely used for direct logging. Consequently these methods on the new PrintStreams proxy directly to the old System.out/err PrintStreams, allowing these logging frameworks to work as before.

Other SLF4J implementations may not fit this useful pattern. They can be registered with sysout-over-slf4j via static methods on the SysOutOverSLF4J class to permit them to access the console.

What about the overhead?

The overhead for Log4J, JULI and Logback when printing to the console should be minimal, for the reasons outlined above. The overhead for any SLF4J implementation that needed to be registered will be greater; on every attempt by it to print to the console its fully qualified classname has to be matched against registered package names in order to determine whether it should be permitted direct access.

Finally, the overhead of actual System.out and System.err calls will be much greater, due to the expense of generating the thread's stacktrace and examining it to determine the origin of the call. As emphasised above, it would be much better if all logging were done via SLF4J directly and this module were not necessary.

Wednesday, 3 February 2010

Why are dynamic languages particularly associated with being Agile?

It could just be me but there's quite a strong association in my mind between Agile development methodologies and dynamic, weakly typed languages - particularly Ruby and Groovy, though again that's possibly skewed by personal experience.

At one level I can see it - more power can indeed sometimes allow you to produce business value faster. There's also the testing angle; dynamic languages are peculiarly associated with rigorous unit testing in part because you really can't afford not to, as the compiler isn't going to catch a lot of programming errors.

At another level, however, it seems to me that a mature, strongly typed, static language is actually much more in tune with my understanding at least of Agile values & principles. Fast feedback is a major part of the way the teams I've worked on do Agile - we release weekly so that new features are in front of the customers as soon as possible so we can evaluate whether they were a good idea or not. We integrate continuously and run automated regression tests to discover bugs fast. We do short (<=3 day) stories so that the results can be in front of the business as soon as possible. We slice our stories so that QA are looking at functional portions of them before they are complete. We test drive from the top down using functional tests and then unit tests to find out as early as possible what errors there might be in our code. It's all about keeping the feedback loop as tight as possible.

And here's where it seems to me a strongly typed, static language like Java can be more "agile" - because a good IDE like Eclipse or IntelliJ will give a much, much faster feedback loop on basic programming errors than running unit tests. Yes, there are ways that you can speed up the running of tests (though sadly it looks like JUnit Max has not seen wide enough adoption to keep it going) but they still aren't going to be up there for speed with the automated test (for that is what it is) that is a background compiler checking your code for correctness.

Then of course there are the other benefits of a strong type system to an Agile way of working. The code is the documentation - it should be so good, the abstraction levels so clear and well named that you don't need anything else to tell you how to use it. What could be more in keeping with that than compiler checked (and therefore guaranteed never to be out of date) documentation of the types expected and returned from a method? (That, incidentally, has always seemed to me the primary benefit of generics - not that it saves you from programming errors that hardly anyone ever made, but that they document what you are expected to pass in that List argument or receive back in that Map in the 3rd party library you are using.)

In addition there's the straight forward speed of turning ideas into execution - a good IDE with code completion saves you even making that typo in the first place. And it can suggest to you that method name you were pretty sure was on the class but can't quite remember (I was chatting the other day to someone who admitted to often strongly typing his groovy variables in order to get code completion from the IDE and then changing them back to def afterwards!)

Finally there's the limitations of tests. It's possible to overestimate the safety given by rigorous unit testing. Don't get me wrong, it's vital, and I'm not for a moment suggesting that a static, strongly typed language is a rationale for not writing rigorous unit tests; just that it is inherently impossible to write exhaustive tests that check every possible state and input, and hence impossible to be absolutely confident in the behaviour of a piece of code from its tests. Static, strong typing helps here. By enforcing the type of an argument it both saves you from writing some required tests and reduces the field of possible inputs that no-one could possibly test exhaustively. Consider Fantom's null type system - by giving you absolute confidence as to that a method does not accept a null argument it saves both the caller from testing its behaviour when passed null and the writer of the method from writing a test for when null is passed in to document (and reassure himself!) as to what occurs. Again I'd argue that the compiler is here acting as a low level unit test in itself that is proving some of the behaviour of your code for "free" - which speeds you up and adds quality.

I wonder how far the dynamic/agile association is actually a result of the verbose nature of Java and its standard libraries? Returning to it from Groovy you do notice quite how much extra boilerplate you are putting round simple ideas, and whilst that actual typing doesn't bother me much after years making it second nature the layer of obfuscation when I come to read it back a day/week/month later certainly does. I've been reading and playing with Scala lately, and whilst I have some reservations (for a language that claims to be ridding us of Java's special cases it seems to have an awful lot of head spinning special cases of its own...) it does demonstrate how concise and powerful a static strongly typed language can be.

The problem as I see it at present for those like me who see real benefits in these features is that many of the benefits listed above are realised primarily in the presence of a really state of the art IDE. My experience of IDE support for Fantom and Scala* (the Java++ flavours I find most appealing) is that it's a long, long way behind say Eclipse's Java support. Which is unsurprising, but does I feel rather undermine their selling point. The fact that their developers aren't selling them (well, not for money at any rate) may be related to that! Still, I feel that in a perfect world language and IDE development would go hand in hand. Anyone up for developing a new language based on incrementally altering Eclipse's JDT?

Friday, 29 January 2010

Checked and Unchecked Exceptions

I've just been reading this article on the hoary old topic of checked exceptions: http://www.artima.com/intv/handcuffs.html

Professionally I currently use Groovy on a day to day basis, so I no longer have to deal with checked exceptions at all. And I do notice the irritation factor when I return to Java land for some home projects; indeed, looking over a recent project I find that I just about always wrap any checked exception thrown as the cause of a RuntimeException.

Yet in many ways I find the idea of checked exceptions very appealing - I've been caught in the past in Groovy land with Hibernate exceptions at runtime that frankly I should have been handling, but wasn't, and cursed the fact that nothing made me pause to think about what could go wrong. It is an attractive idea that the compiler should not only tell me what parameters a method expects and what it will return, but also give me a heads up on what might go wrong that I might like to think about.

The standard Java answer is "use checked exceptions for recoverable conditions and unchecked for unrecoverable conditions". But this seems to me to ignore a lesson we have all learnt over the years - you don't know what clients of your code want or care about. Choosing what conditions your clients will regard as recoverable and what conditions they will regard as unrecoverable at the time of writing a library is impossible. You may make a RuntimeException which actually they would really like to have known about, and a checked exception that they cannot possibly handle and are quite happy to let bubble up to the top of the stack and blow up the programme. It also ignores the third (and I would say one of the most common) class of exceptions - the exception which is perfectly plausible in the code that would throw it, but which the calling code happens to know (or think it knows!) cannot logically occur. As far as the code is concerned one of these ought really to be checked - it's an important possibility for the writer of any client code to think about. But the writer of the client code, having thought about it and concluded it can make the call in a way that makes it impossible for the exception to occur, will then wish it was a RuntimeException to save them the hassle of persuading the compiler it has been handled.

Take ArrayIndexOutOfBoundsException. It's unchecked, yet I'd bet that it would actually have been a profoundly useful one over the years had it been checked - loads of thoughtless programmers must have whacked a [0] onto an array over the years, blithely assuming it will always have a first element, and paid the penalty later. A compiler complaining about a checked exception might have encouraged them to check the array's length in code first, or at least re-examine their assumption that the array always has a first element - perhaps look at the documentation or the code of the array provider. And of course it is highly likely it represents a recoverable condition in some cases.

So why was it made a RuntimeException? Because it's so massively arduous to persuade the compiler that you have thought about a checked exception. A try/catch block with indented code is very ugly to the eye, a genuinely expensive bit of boilerplate; putting it round every array access in order to re-throw that checked exception as the cause of a runtime one is clearly absurd. It would be even worse to add it to the throws clause of the method, thereby proliferating it right the way up the stack to code that shouldn't have a clue an array had been accessed much less be trying to handle the fact that it had been accessed wrongly.

What would be nice is some way to allow methods to declare the exceptions they genuinely believe they might throw in a way that alerts the writer of client code to consider those cases, without having to make a guess as to whether they represent recoverable conditions or not for that client. Effectively, make a lot more* exceptions checked by default. However for that to work it has to be really easy for the writer of the client code to indicate to the compiler "yes, thought about it - not interested in doing anything with it". And thereby change it from a checked to an unchecked exception, so that it can still make its way up the stack if it does happen without forcing clients further up the stack to pollute their methods with throws clauses or try/catch blocks for exceptions that someone nearer the cause has already decided don't need handling beyond the default thread ending behaviour.

So my tentative idea is to have an "unchecked" annotation, so that any line of code preceded by @unchecked has any exceptions declared in the methods it calls changed to runtime ones that neither need to be handled nor declared in the methods throw signature. Something like this:

void foo() throws FooException {...}
// does not compile - unhandled FooException
void bar1() {
    foo();
}

// compiles
void bar2() {
   @unchecked
   foo();
}

This could be extended to allow the annotation to make specific exception types unchecked, as so:

// All 4 of these represent different conditions that may well happen depending on where and how foo is called
void foo() throws Foo1Exception, Foo2Exception, Foo3Exception, Foo4Exception {
....
}

void bar() throws Foo1Exception { //can't sensibly handle Foo1Exception in this method but it is likely to happen so warn clients to think about it...
   try {
       @unchecked(Foo3Exception.class, Foo4Exception.class) // Nothing sensible anyone can do with these if they happen
       foo();
   } catch (Foo2Exception fe) {
       // it makes sense to handle Foo2Exception here
   }
}

To my mind this has several benefits:

  1. It will discourage methods that throw the API wrapping checked MyApiException that actually tells you nothing about what it might represent other than "something went wrong in this library". We use these because it's so arduous to handle multiple exceptions in a throws clause, but they in many ways actually represent unchecked exceptions - they give you no documentation value in terms of what the actual problem might be and what you might do about it. You already know the method is in library A and you already know that any method call can result in an exception - what have you gained, other than being forced to do something with it or pass the buck to whoever calls your method?
  2. The default thing for the lazy programmer to do when faced with calling a method that throws an exception will be to add @unchecked - easier than adding a throws clause that breaks calling methods, far easier than try/catch with an empty catch block. Which means no inconvenience to programmers working up the stack and no swallowed exceptions.
  3. It will encourage people to declare what exceptional conditions their code may encounter that you really might like to think about, even if they don't share a nice common supertype, because they will know they aren't making your life a misery if you aren't interested in them
  4. It will make it easy for the thoughtful programmer who has rightly come to the conclusion that there is nothing they can do with an exception (or that it cannot occur) to choose not to handle it
  5. Stack traces are more likely to start with the actual problem higher up the chain, rather than nested 5 down in the chain as each layer dutifully catches all exceptions and rethrows them in its own abstraction exception that tells you nothing other than that it occurred in that layer - which you knew from the stack trace anyway

* I'm not seriously suggesting ArrayIndexOutOfBoundsException should be one of them! There are clearly going to be some types of very, very common exceptions that have to be RuntimeExceptions or every other line of code would be @unchecked and the result would be illegible. A programmer has to be expected to know about and think about these without prompting, even if most of us have failed to do so at some point.