[Netcommon-developer] Logging Context

[Geoghegan, W. A (Willie) <wil...@in...>]

Common.Logging team - I know that are busy right now, but take a look at
this when you have some time and let me know your thoughts.

I have implemented logging context abstractions for NLog and log4net
(and also for Trace.CorrelationManager.LogicalOperationStack).  For the
most part, I followed the model of Castle's logging context abstraction.
For now, I have kept it separate from the actual Common.Logging
projects.  My approach was to define an interface by which a logging
abstraction implementation (ILoggerFactoryAdapter) could return one or
more objects that wrap the underlying logging framework's context.  I
implemented a static object, LogContext, that is parallel to LogManager
which exposes the logging context.  Internally LogContext gets the
LogManager.Adapter property and tries to get the interface that exposes
the logging context.  I modified (copied and created new versions) the
NLog and log4net logging abstractions to implement the interface.  So,
when I configure Common.Logging to use my NLog adapter, for example, the
adapter is able to hand out an interface that wraps the NLog context
api.

Sample code (assumes that Common.Logging is configured to use my NLog
adapter)

LogContext.GlobalProperties["starttime"] = DateTime.Now;
LogContext.ThreadProperties["sessionid"] = GetMySession().Id;
LogContext.ThreadProperties["myguid"] = Guid.NewGuid();

using (LogContext.ThreadStacks["ndc"].Push("outer scope"))
{
  DoSomething();
  using (LogContext.ThreadStacks["ndc"].Push("inner scope"))
  {
  }
}

The net effect of these lines is that values were inserted into NLog's
GDC and MDC and two values were pushed onto (and popped from) the NLog
NDC.

Here are the interfaces that I implemented:

IAdapterContextProvider  is implemented by any adapter that wants to
expose a logging context api.  If I had modified the Common.Logging
source, I probably would have just added a Context property (as this
interface defines) directly to the ILoggerFactoryAdapter interface.

public interface IAdapterContextProvider
{
  IAdapterContext Context { get; }
}

An implementation of the IAdapterContext interface is returned by any
adapter that wants to expose a logging context api.  If something like
this is provided by Common.Logging for each delivered adapter that
supports a logging context api (NLog, log4net, etc), then I think that
the implementation should be reusable (i.e. in its own object, not as
part of an adapter implementation).  That way, if I want to make my own
NLog abstraction for some reason I could use the already-existing
context api implementation.

This interface allows for the exposure of NLog's GDC (GlobalProperties),
MDC (ThreadProperties), and NDC (ThreadStacks["ndc"]).  It also allows
for the exposure of log4net's GlobalContext.Properties,
ThreadContext.Properties, and ThreadContext.Stacks.  It does not allow
exposure of log4net's LogicalThreadContext.Properties and
LogicalThreadContext.Stacks.  My implementation mostly mimics Castle's
implementation and they did not expose the "Logical" context
information, so I didn't.  I don't know if it should be exposed
generically or not (since NLog does not have an equivalent concept).  It
might be a good idea to expose the "Logical" context on the chance that
someone wants to implement a "Logical" context similar to log4net's
(i.e. uses CallContext to store "Logical" context information) to store
context information and then implement the corresponding NLog
LayoutRenderer to output the information from the context.  I haven't
used log4net or NLog enough to have a strong opinion about this.

public interface IAdapterContext
{
  IContextProperties GlobalProperties { get; }
  IContextProperties ThreadProperties { get; }
  IContextStacks ThreadStacks { get; }
}

The IContextProperties interface exposes a dictionary-like interface
that is a very thin wrapper around the underlying logging framework's
context dictionary objects.  For some reason, Castle exposes only the
indexer.  It seemed to me that they should have also exposed to Clear
and Remove to allow for cleaning up the dictionary (don't know if this
is common, but NLog and log4net both expose Clear and Remove).

public interface IContextProperties
{
  object this [string key] { get; set; }
  void Clear();
  void Remove(string key);
}

The IContextStacks interface exposes a dictionary of context stacks.
This concept (dictionary of stacks) exists in log4net but not in NLog
(which has only a single stack, NDC).  The Castle implementation always
returns the NDC stack in the case of their NLog abstraction.

public interface IContextStacks
{
  IContextStack this[string key] { get; }
}

Should this have a Clear and/or Remove to clear or remove a particular
stack?  I don't know.

The IContextStack interface exposes a stack interface for providing a
"logical operation stack" context.  It is a thin layer over the
underlying "stack" implementation.

public interface IContextStack
{
  int Count { get; }
  void Clear();
  string Pop();
  IDisposable Push(string message);
}

Nothing really earth shattering here, except maybe for the fact that
Push returns an IDisposable, thus enabling the using(blah.Push["scope"])
syntax for providing a logical scope around some code.

Where I exposed all of these through a separate object, LogContext, I
think that it makes sense to expose them through the LogManager.
LogManager could look something like this:

public static class LogManager
{
  //GetLogger, etc ...
  IContextProperties GlobalProperties
  {
    get
    {
      return Adapter.ContextProvider.Context.GlobalProperties;
    }
  }
  IContextProperties ThreadProperties
  {
    get
    {
      return Adapter.ContextProvider.Context.ThreadProperties;
    }
  }
  IContextStacks ThreadStacks
  {
    get
    {
      Return Adapter.ContextProvider.Context.ThreadStacks;
    }
  }
}

(Alternatively, these context objects could be exposed as static objects
directly from the Common.Logging namespace (or maybe a
Common.Logging.Context namespace).  What actually gets returned could
work the same way - pull it from the current value of LogManager.Adapter
)

The assumption is that each of these properties exposed by LogManager is
never null.  A "NullContext" object would be provided (probably a
NullContext as well as null implementations of each interface).  By
default, if an Adapter does not support IContextProvider (or if the
value is null), then a NullContext would be returned (similar to the
NoopLogger and NoopLoggerAdapter).  If someone writes an adapter and can
(or chooses to) only expose some context, then that developer could
return the "null" implementation for each context that they do not
provide.  For example, if someone wrote a logging adapter for
System.Diagnostics using TraceSources, they might choose to only expose
the Trace.CorrelationManager.LogicalOperationStack (as
IContextStacks/IContextStack) and return "NullContextProperties" for
GlobalProperties and ThreadProperties.

What I have implemented actually seems to work pretty well.  I can set
the underlying logging framework's logging context values from my
application code in a manner that is similar to how I would do it if I
were programming directly against the specific framework.

Some comments:
1.  I'm not sure that I really like the ThreadStacks idea, primarily
because I don't know how often people actually take advantage of the
ability to have multiple stacks per thread (in log4net, NLog has only
one stack per thread).  That means that code that uses "stacks" is
cluttered with this pattern:

using (LogManager.ThreadStacks["ndc"].Push("hello"))
{
}

Rather than something like this:

using (LogManager.ThreadStack.Push("hello")
{
}

Having to type the key every time (and making sure not to mistype it) is
not really providing the "pit of success".  On the other hand, as soon
as only one stack is exposed, someone will ask why the context has been
"dumbed down", "I could do it in log4net", etc.  You can imagine...  I
wonder if it would be useful (or, perhaps simply more confusing) to
expose ThreadStack AND ThreadStacks.  If you are using only a single
stack, using ThreadStack would behave AS IF you had called ThreadStacks
passing the same name every time.  By definition, the name could be
"ndc" so that it would be easy to specify the stack information in the
underlying logging framework's output formatting configuration.

Maybe LogManager could expose something like this:

public static class LogManager
{
  IContextProperties GlobalProperties { get {
GetTheGlobalPropertiesFromTheCurrentAdapter(); } }
  IContextProperties ThreadProperties { get {
GetTheThreadPropertiesFromTheCurrentAdapter(); } }
  IThreadStacks ThreadStacks { get {
GetTheThreadStacksFromTheCurrentAdapter(); } }
  IThreadStack ThreadStack { get { return ThreadStacks["ndc"]; } }  //In
effect, "ndc" is the "default" stack
}

This way if you only want to use one stack, you can just use the
ThreadStack property.  If you have a need for multiple stacks, feel free
to use the ThreadStacks property.

2. I'm not 100% comfortable with leaving out log4net's LogicalContext
information (like Castle did). With threading and parallel programming
becoming more and more important, it certainly seems useful to have this
arguably more powerful option for maintaining logging context.
Log4net's LogicalContext.Properties is implemented using a CallContext
(as opposed to Thread.SetData which is used to implement log4net's
ThreadContext.Properties and NLog's MDC).  Theoretically this allows for
the logical properties to be propagated along the call sequence, even
over remoting boundaries.  I'm not sure if this really happens because
log4net uses CallContext.SetData rather than LogicalSetData and log4net
does not implement ILogicalThreadAffinaty (or whatever the interface is)
on the dictionary that they store in the CallContext.  On the other
hand, NLog does not have a similar concept, so what would the
implementation of LogicalThreadProperties for it be?  Would it delegate
to ThreadProperties?  Would it do nothing (NullContextProperties
implementation)?  Could a CallContext-based implementation be provided
so that NLog could be configured (via a custom LayoutRenderer) to output
the values stored in the CallContext?  Could the as-delivered
implementation of LogicalThreadProperties for NLog be NullContext but
someone could still develop a CallContext-based implementation (or based
on whatever technology they want) for their own use and substitute it in
- probably by implementing their own NLog logging adapter - or maybe by
subclassing the NLogLoggerFactoryAdapter and simply overriding the
"LogicalThreadProperties" property, providing their own implementation
for only that context.

I don't want to advocate for some overly complicated solution to the
logging context problem, but I do want to suggest that it might be
better to provide more (or at least the possibility of more if the end
user of Common.Logging wants to put in some work as well) capability
rather than less.

I am willing to send what I have done so far to the Common.Logging team
to see if it is worth including in Common.Logging (assuming you haven't
already implemented this functionality) in some form.  I am also willing
to discuss further if anyone is interested.

I hope this whole message makes it through rather than being too long
again.  I am sending as plain text, not html.

Willie Geoghegan.