[hibernate-dev] Context-based Logging

[John Verhaeg]

I'm currently going through the codebase trying to convert our use of slf4j for logging to jboss-logging.  In doing so, I've noticed that all of the current loggers are named using the package-qualified name of the enclosing class that define them.  JBoss-logging offers a similar concept in that loggers are associated with category names, but with the difference that multiple loggers can be associated with the same category.  

I'm still fairly new to working with the Hibernate codebase, but based on other projects I've worked on, I was thinking that maybe we should *additionally* introduce some type of context-based logging moving forward, where we'd supply logging contexts that represent the processes in play, as opposed to the structural organization of loggers that names / categories typically represent.  To fully realize the power of these contexts, you'd want to support the idea of sub-contexts that could be active within other contexts (capturing when sub-processes are executed within higher-level processes).  

Just to clarify via an example, consider the code involved with making a query using hql.  From what I can see in the existing code, one of the sub-processes involved with such a query involves copying the result set so that a pristine copy can be maintained and cached by the session, such that it won't be impacted by local changes to those results by the user between commits.  So let's assume there's some issue a developer encounters while creating a query, and the underlying problem has something to do with copy sub-process.  Using contexts, the developer would be able to configure his underlying logging framework to enable, say, the "query" context and set the logging level to debug or trace.  Ideally, he'd get enough information from these logs to determine that things begin to go awry after the results are copied.  This, of course, presumes a message is logged in the "query" context indicating when the "copy results" sub-process is triggered, possibly even specifying in that message the sub-context associated with that sub-process.  Now the developer knows to enable this new context and run through the scenario again to isolate the problem.  He doesn't have to care or know which or how many classes are involved in either the outer hql process or the subprocess responsible for copying results.

So one intended benefit of using contexts would be to make it easier for developers, and possibly even developers' end-users, to determine which log messages to enable/filter related to some problem their trying to hunt down, while minimizing their need to understand the structure of code internal to the Hibernate libraries.  This approach should also help decouple the logging and coding concerns such that, for instance, if a method is moved to a different class, there is no impact on how messages are logged (assuming the same contexts are still applicable).

While we certainly could specify category names that more represent processes or logical structure rather than simple package and class names (physical structure), I'd still be concerned about code that happens to be reused within multiple processes or services.  Assuming it's important for a significant amount of this type of "utility" code to log messages (this might be a big assumption), which category of logger would you choose?  You could pass in the logger, but that would require changes to any existing APIs.  You could also just provide a separate category for this type of code, but then you'd blurring what it means for a category to represent a "process".

So I'm thinking that using the jboss-logging NDC facility might be a good way to support process-based contexts.  This facility allows us to push and pop contexts on and off a global stack (maintained by the jboss-logging framework) at the boundaries of these processes.  Of course, we'd have to document the contexts that we use and the processes that they're tied to.  The disadvantage here would be the discipline we'd have to exercise to do this properly.  Pushing and popping contexts would need to be treated similarly to beginning and ending a transaction, where contexts that are popped off of the NDC stack would reside within finally blocks.  One other thing to consider is we'd probably want to provide some documentation about how to support NDC using simple JDK logging, since this isn't supported out-of-the-box.

So is any of this worth the effort?  Are my concerns valid?  Is using category names to represent logical structure enough?  Thoughts?

JPAV