There's an unfortunate issue in between the Common.Logging and log4Net we've stumbled upon.
The problem is related to so called event specific properties, additional values that should be logged and are usually added per log call. In the pattern layout, these additional properties
are specified using the %P, e.g.
<layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%newline%date [%thread] [%P{vFoo} %P{vBar}] %-5level - %message" /> </layout>
In the above example, the two additional properties, vFoo and vBar are injected into the logger and their values are part of the log entries.
If log4net is used directly, you just set your properties, either in a global context (properties set once and shared), in a thread context or a logical thread context
ILog logger = LogManager.GetLogger( typeof( Program ) ); // shared GlobalContext.Properties["vFoo"] = 5; GlobalContext.Properties["vBar"] = 5; // per thread (doesn't work with async/await) ThreadContext.Properties["vFoo"] = 5; ThreadContext.Properties["vBar"] = 5; // per logical thread (works correctly over async/await) LogicalThreadContext.Properties["vFoo"] = 5; LogicalThreadContext.Properties["vBar"] = 5;
The distinction between the last two is a strict motivation to write this entry. Note that putting properties in a thread context (implemented with log4net using
ThreadStatic) could be useful in some
scenarios but doesn't support async/await, mainly, when the continuation runs in a different thread, properties are lost. That's what the logical thread context does, it's implemented using the
CallContext
and properties are properly preserved in async/await code.
Now, move to Common.Logging which is commonly used as a wrapper over specific loggers. Common.Logging logger supports global variables context and thread variables context:
var log = LogManager.GetLogger( typeof( Program ) ); // shared log.GlobalVariablesContext.Set( "vFoo", 5 ); log.GlobalVariablesContext.Set( "vBar", 5 ); // per thread log.ThreadVariablesContext.Set( "vFoo", 5 ); log.ThreadVariablesContext.Set( "vBar", 5 );
And where's the logical thread context?
Nowhere, it's missing from Common.Logging. Namely ...
var log = LogManager.GetLogger( typeof( Program ) ); log.ThreadVariablesContext.Set( "vFoo", 5 ); log.ThreadVariablesContext.Set( "vBar", 5 ); log.Debug( "foo bar hello" ); await Task.Delay( 1 ); log.Debug( "foo bar hello 2" ); await Task.Delay( 1 ); log.Debug( "foo bar hello 3" );
... will log both variables correctly only the first time and will log (null) in two subsequent calls.
Problem here is that log4net is supposed to search for variables set only using one it's own three classes presented earlier, GlobalContext, ThreadContext or the LogicalThreadContext.
And when Common.Logging is used throughout the application stack, there's no way to call any of the three directly.
Our approach was to create a proxy logger and replace the log manager factory with one that returns the proxy logger. The proxy logger would reimplement the ThreadVariablesContext to use
the other way of storing thread variables.
Let's start with the factory. It's supposed to be defined down the stack, so that it can be used everywhere. Since it can't use log4net directly, we'll use the common pattern to make
the context factory injectable from within the Composition Root
public class VLogManager { static Func<IVariablesContext> _variablesContextFactory; public static void SetVariablesContextFactory( Func<IVariablesContext> variablesContextFactory ) { _variablesContextFactory = variablesContextFactory; } public static ILog GetLogger( Type t ) { return new WrappedLogger( LogManager.GetLogger( t ), _variablesContextFactory() ); } }
Now comes the proxy logger, defined somewhere near the custom log manager. The logger is not supposed to use log4net, too
public class WrappedLogger : ILog { private ILog _log; private IVariablesContext _logicalThreadVariablesContext; public WrappedLogger( ILog log, IVariablesContext localVariablesContext ) { this._log = log; this._logicalThreadVariablesContext = localVariablesContext; } public bool IsTraceEnabled { get => _log.IsTraceEnabled; } public bool IsDebugEnabled { get => _log.IsDebugEnabled; } public bool IsErrorEnabled { get => _log.IsErrorEnabled; } public bool IsFatalEnabled { get => _log.IsFatalEnabled; } public bool IsInfoEnabled { get => _log.IsInfoEnabled; } public bool IsWarnEnabled { get => _log.IsWarnEnabled; } public IVariablesContext GlobalVariablesContext { get => _log.GlobalVariablesContext; } public IVariablesContext ThreadVariablesContext { get => this._logicalThreadVariablesContext; } public INestedVariablesContext NestedThreadVariablesContext { get => _log.NestedThreadVariablesContext; } public void Debug( object message ) { _log.Debug( message ); } public void Debug( object message, Exception exception ) { _log.Debug( message, exception ); } public void Debug( Action<FormatMessageHandler> formatMessageCallback ) { _log.Debug( formatMessageCallback ); } public void Debug( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Debug( formatMessageCallback, exception ); } public void Debug( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Debug( formatProvider, formatMessageCallback ); } public void Debug( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Debug( formatProvider, formatMessageCallback, exception ); } public void DebugFormat( string format, params object[] args ) { _log.DebugFormat( format, args ); } public void DebugFormat( string format, Exception exception, params object[] args ) { _log.DebugFormat( format, exception, args ); } public void DebugFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.DebugFormat( formatProvider, format, args ); } public void DebugFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.DebugFormat( formatProvider, format, exception, args ); } public void Error( object message ) { _log.Error( message ); } public void Error( object message, Exception exception ) { _log.Error( message, exception ); } public void Error( Action<FormatMessageHandler> formatMessageCallback ) { _log.Error( formatMessageCallback ); } public void Error( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Error( formatMessageCallback, exception ); } public void Error( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Error( formatProvider, formatMessageCallback ); } public void Error( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Error( formatProvider, formatMessageCallback, exception ); } public void ErrorFormat( string format, params object[] args ) { _log.ErrorFormat( format, args ); } public void ErrorFormat( string format, Exception exception, params object[] args ) { _log.ErrorFormat( format, exception, args ); } public void ErrorFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.ErrorFormat( formatProvider, format, args ); } public void ErrorFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.ErrorFormat( formatProvider, format, exception, args ); } public void Fatal( object message ) { _log.Fatal( message ); } public void Fatal( object message, Exception exception ) { _log.Fatal( message, exception ); } public void Fatal( Action<FormatMessageHandler> formatMessageCallback ) { _log.Fatal( formatMessageCallback ); } public void Fatal( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Fatal( formatMessageCallback, exception ); } public void Fatal( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Fatal( formatProvider, formatMessageCallback ); } public void Fatal( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Fatal( formatProvider, formatMessageCallback, exception ); } public void FatalFormat( string format, params object[] args ) { _log.FatalFormat( format, args ); } public void FatalFormat( string format, Exception exception, params object[] args ) { _log.FatalFormat( format, exception, args ); } public void FatalFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.FatalFormat( formatProvider, format, args ); } public void FatalFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.FatalFormat( formatProvider, format, exception, args ); } public void Info( object message ) { _log.Info( message ); } public void Info( object message, Exception exception ) { _log.Info( message, exception ); } public void Info( Action<FormatMessageHandler> formatMessageCallback ) { _log.Info( formatMessageCallback ); } public void Info( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Info( formatMessageCallback, exception ); } public void Info( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Info( formatProvider, formatMessageCallback ); } public void Info( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Info( formatProvider, formatMessageCallback, exception ); } public void InfoFormat( string format, params object[] args ) { _log.InfoFormat( format, args ); } public void InfoFormat( string format, Exception exception, params object[] args ) { _log.InfoFormat( format, exception, args ); } public void InfoFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.InfoFormat( formatProvider, format, args ); } public void InfoFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.InfoFormat( formatProvider, format, exception, args ); } public void Trace( object message ) { _log.Trace( message ); } public void Trace( object message, Exception exception ) { _log.Trace( message, exception ); } public void Trace( Action<FormatMessageHandler> formatMessageCallback ) { _log.Trace( formatMessageCallback ); } public void Trace( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Trace( formatMessageCallback, exception ); } public void Trace( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Trace( formatProvider, formatMessageCallback ); } public void Trace( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Trace( formatProvider, formatMessageCallback, exception ); } public void TraceFormat( string format, params object[] args ) { _log.TraceFormat( format, args ); } public void TraceFormat( string format, Exception exception, params object[] args ) { _log.TraceFormat( format, exception, args ); } public void TraceFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.TraceFormat( formatProvider, format, args ); } public void TraceFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.TraceFormat( formatProvider, format, exception, args ); } public void Warn( object message ) { _log.Warn( message ); } public void Warn( object message, Exception exception ) { _log.Warn( message, exception ); } public void Warn( Action<FormatMessageHandler> formatMessageCallback ) { _log.Warn( formatMessageCallback ); } public void Warn( Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Warn( formatMessageCallback, exception ); } public void Warn( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback ) { _log.Warn( formatProvider, formatMessageCallback ); } public void Warn( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception ) { _log.Warn( formatProvider, formatMessageCallback, exception ); } public void WarnFormat( string format, params object[] args ) { _log.WarnFormat( format, args ); } public void WarnFormat( string format, Exception exception, params object[] args ) { _log.WarnFormat( format, exception, args ); } public void WarnFormat( IFormatProvider formatProvider, string format, params object[] args ) { _log.WarnFormat( formatProvider, format, args ); } public void WarnFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args ) { _log.WarnFormat( formatProvider, format, exception, args ); } }
Note how boring the proxy is, it merely delegates everything to the logger it wraps. The only part that is reimplemented is the ThreadVariablesContext.
public IVariablesContext ThreadVariablesContext { get => this._logicalThreadVariablesContext; }
Now, let's move to the Composition Root of the application stack, the place close to Main or Application_Start, where all references are available. This
is where the variables context implementation can be provided
public class LogicalThreadVariablesContext : IVariablesContext { public void Set( string key, object value ) { LogicalThreadContext.Properties[key] = value; } public object Get( string key ) { return LogicalThreadContext.Properties[key]; } public bool Contains( string key ) { return LogicalThreadContext.Properties[key] != null; } public void Remove( string key ) { LogicalThreadContext.Properties.Remove( key ); } public void Clear() { LogicalThreadContext.Properties.Clear(); } }
Note that this is where we are allowed to reference log4net! And the last piece - inject this class into the custom logger factory. Specifically, add this to Main or Application_Start
VLogManager.SetVariablesContextFactory( () => new LogicalThreadVariablesContext() );
This is it. Now, anywhere in your application stack you can inject custom variables into the logger ...
var log = VLogManager.GetLogger( typeof( Program ) ); log.ThreadVariablesContext.Set( "vFoo", 5 ); log.ThreadVariablesContext.Set( "vBar", 5 ); log.Debug( "foo bar hello" ); await Task.Delay( 1 ); log.Debug( "foo bar hello 2" ); await Task.Delay( 1 ); log.Debug( "foo bar hello 3" );
... and values are properly stored in the log. Note that the only change in client's code is the usage of the newly introduced log manager (VLogManager instead of the provided LogManager).
No comments:
Post a Comment