[hibernate-dev] Context-based Logging

Tue Oct 19 13:07:11 EDT 2010

On Oct 19, 2010, at 11:26 AM, Steve Ebersole wrote:

> 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.

I've just realized there's an expectation I had for supporting contexts I failed to convey: My expectation is that the handlers/filters for the underlying logging framework would not only ensure the NDC context values are used, but also that they'd offer users a way to filter messages based upon those contexts.  I should also state that by "set the logging level to debug or trace", I should have said within the global logger, assuming that level is inherited by all child loggers.

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

JPAV