Wednesday 8 September 2010

When is a log() statement not just a log() statement?

Came across the following interesting situation today in a Groovy app we're developing.

We read some data into a ByteArrayInputStream, in order to pass it into a shared interface that takes an InputStream as argument. Stopping the code in the debugger at this point shoes that the stream cursor is set at the first byte.

Stepping through into the service that implements the interface, the same InputStream now has it's cursor set at the end of the stream?! (And hence, iterating through it won't return any data.) As we're passing in a ByteArrayInputStream, we can call reset(), but not every InputStream implementation supports reset(), and the interface we're calling expects a generic InputStream. But, more fundamentally, why has the InputStream cursor moved from the start to the end of the stream anyway? What's going on?

Well, first thing to mention is that the implementation uses a standardised parameter-checking piece of code, that is injected into the code via the Groovy meta-class mechanism. So between passing the stream to the interface, and the implementation seeing it, it's been through the parameter-checker.

Within the parameter-checker is the offending line of code:

log.debug("parameter ${name} -> ${value}")

originally written with the expectation that the value would be a simple primitive. Here, value is the InputStream. So, in order to construct the log statement (whether or not our logger config is set up to display it or not, as we've omitted the recommended if(log.isDebugEnabled()) clause), we call Groovy's GString interpolator on our InputStream, which - guess what? - reads through the stream (not, as I would have expected, calling InputStream.toString()).

So, main lessons from this for today:
  • Injecting code in sideways via meta-programming techniques is great, but don't forget that it's there!
  • GString variable interpolation isn't always the same as calling toString()

Here's a sample Groovy script that demonstrates the issue in a nutshell:
def bytes=new Byte[5];
bytes[0]='h';
bytes[1]='e';
bytes[2]='l';
bytes[3]='l';
bytes[4]='o';
def is=new ByteArrayInputStream(bytes)

println "BEFORE: bytes available - ${is.available()}"
println is.toString()
println "AFTER toString(): bytes available - ${is.available()}"
println "stream ${is}"
println "AFTER interpolation: bytes available - ${is.available()}"

resulting in this:

BEFORE: bytes available - 5
java.io.ByteArrayInputStream@104ce99
AFTER toString(): bytes available - 5
stream hello
AFTER interpolation: bytes available - 0

UPDATE: If you want to have a play with the script, it's at the funkadelic Groovy Web Console here.

Thanks to Al & Gav at HF for helping to dig this one out!

3 comments: