Log debug and Hibernate, a tale of two environments

Cute story.

A couple of years back I got a call for support with a recently released webapp. User is complaining that a particular functionality was returning the following hibernate exception.

org.hibernate.LazyInitializationException: could not initialize proxy – the owning Session was closed

A quick source check have indeed shown that the field in question was lazy initialised when it should not have been. But the puzzle remains, it worked in UAT environment. In fact it was extensively tested by the particular user who reported the issue before it was released into production. Not to mention all the developer testing that was done.

The simple explanation would be, we simply missed that particular functionality when we did the test. But that was soon ruled out as in UAT, the bug was still not rearing it’s ugly stack trace. So, what was it in production that is making it fail?

As it turned out, the correct question should be, what was in UAT that made it work? This:

if (logger.isDebugEnabled()) {    
  logger.debug(dataMap.toString());
}

The reason it was working UAT was because log was set to debug in that environment, while in production it was set to info only. Having the dataMap.toString() called in that debug block means hibernate actually went and fetched the lazy initialised data, as oppose to in production where the first time the code needed dataMap, the hibernate session was already closed.

I’m still not sure what exact lesson I should take away from this, but it sure was an interesting code mystery.

Tagged ,