[hibernate-dev] Context-based Logging

[Steve Ebersole]

On Tuesday, October 19, 2010, at 11:07 am, John Verhaeg wrote:
> 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. 

This is a bit of a misnomer I think.  First, I think we need to say that the 
"context logging" is NDC/MDC based.  I do not know of a framework that has 
built in support for specifying log levels/granularity based on NDC/MDC that 
is the realm of the category in every framework of which I am aware.  What you 
suggest is possible by, for example, cranking up logging all the way and then 
using the framework's notion of a filter.  But the "problem there" is stuff 
like logger.isDebugEnabled(), etc will return true there all the time if they 
go that route.

And as I have said all along, basing category names on this "context" is not 
feasible.

> 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
> 
> 
> 
> 
> 
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev

---
Steve Ebersole <steve at hibernate.org>
http://hibernate.org