New code to allow formatting during logging

["de la Torre, Douglas" <de...@ugs.com>]

Hi All,

I'm including code that would allow the logging methods to work like
Console.WriteLine or string.Format.

For example, the changes below make it convenient to do something like: 
	 
	log.Debug( "message with params {0} and {1}", param1, param2 )
			
without needing to use string.Format

	log.Debug( string.Format( "message with params {0} and {1}",
param1, param2 ) )

Since string.Format is null-friendly and also has the potential to defer
string-building overhead until the string is actually consumed, I
noticed I had written many logging statements in my own code that look
like this:

	if( log.IsDebugEnabled ) log.Debug( string.Format( "message with
params {0} and {1}", param1, param2 ) )

The changes below can be applied to the LogImpl class, to give it the
ability to absorb the functionality of string.Format to make this easier
and let me eliminate lots of duplication.

I included unit tests and also checked to see that it is backward
compatible with the existing calls that currently pass a message and
exception.

Note 1)  For this to work, the ILog interface would need to add the
methods that take the params, and remove the methods that take an
exception, otherwise when someone passes a message with {0} and a single
parameter with an exception, the specific method will be called rather
than the generic one taking params, and thus no formatting substitution
would occur.

Note 2)  If the ILogger object doesn't use Exception.ToString() then
using the format specifier {0} would potentially produce a different
result than calling a method like Debug( message, ex ).  In cases where
the exception is the sole parameter, since it falls back, no change
would be seen.  Only new code that introduced two exceptions would see
this.  Assuming the ToString method of the exception is used, this is a
non-issue.

What do you think?  Is the output formatting code below useful?

-Doug

Doug de la Torre
Lead Developer
UGS



------------------

using System;
using System.Collections;

using log4net;
using log4net.spi;

#if NUNIT_TESTS
using NUnit.Framework;
#endif

namespace Log4netWrappers
{
	/// <summary>
	/// Placeholder class to put a 'new' implementation of the
LogImpl code.
	/// 
	/// Note that the main purpose of this class is to remove the
overloaded
	/// methods that previously took an exception as a separate
parameter,
	/// and roll this functionality into a more generic method that
takes
	/// arbitrary parameters, like <see cref="string.Format"/> does.
	/// 
	/// These changes make it convenient to do something like: 
	/// 
	///		log.Debug( "message with params {0} and {1}",
"param1", "param2" )
	///		
	/// without needing to use 
	/// 
	///		log.Debug( string.Format( "message with params
{0} and {1}", "param1", "param2" ) )
	///		
	///	and replace the previous method that took a message and
an exception
	/// </summary>
	public class MyLogImpl
	{
		ILogger logger;

		string m_fullName;

		/// <summary>
		/// Constructor
		/// </summary>
		/// <param name="logger"></param>
		public MyLogImpl( ILogger logger )
		{
			this.logger = logger;
			this.m_fullName = base.GetType().FullName;
		}

		public ILogger Logger
		{
			get
			{
				return logger;
			}
		}

		public void Debug(object message)
		{
			this.Logger.Log(this.m_fullName, Level.DEBUG,
message, null);
		}

		public void Info(object message)
		{
			this.Logger.Log(this.m_fullName, Level.INFO,
message, null);
		}

		public void Warn(object message)
		{
			this.Logger.Log(this.m_fullName, Level.WARN,
message, null);
		}

		public void Error(object message)
		{
			this.Logger.Log(this.m_fullName, Level.ERROR,
message, null);
		}

		public void Fatal(object message)
		{
			this.Logger.Log(this.m_fullName, Level.FATAL,
message, null);
		}

		#region Methods that are no longer needed

		//		public void Debug(object message,
Exception t)
		//		{
		//			this.Logger.Log(this.m_fullName,
Level.DEBUG, message, t);
		//		}
		//
		//		public void Info(object message,
Exception t)
		//		{
		//			this.Logger.Log(this.m_fullName,
Level.INFO, message, t);
		//		}
		//
		//		public void Warn(object message,
Exception t)
		//		{
		//			this.Logger.Log(this.m_fullName,
Level.WARN, message, t);
		//		}
		//
		//		public void Error(object message,
Exception t)
		//		{
		//			this.Logger.Log(this.m_fullName,
Level.ERROR, message, t);
		//		}
		//
		//		public void Fatal(object message,
Exception t)
		//		{
		//			this.Logger.Log(this.m_fullName,
Level.FATAL, message, t);
		//		}

		#endregion

		#region New methods that replace the single exception
parameter, and allow arbitrary params

		public void Debug( object message, params object[]
parameters )
		{
			LogFormatted( Level.DEBUG, message, parameters
);
		}

		public void Info( object message, params object[]
parameters )
		{
			LogFormatted( Level.INFO, message, parameters );
		}

		public void Warn( object message, params object[]
parameters )
		{
			LogFormatted( Level.WARN, message, parameters );
		}

		public void Error( object message, params object[]
parameters )
		{
			LogFormatted( Level.ERROR, message, parameters
);
		}

		public void Fatal( object message, params object[]
parameters )
		{
			LogFormatted( Level.FATAL, message, parameters
);
		}

		#endregion

		/// <summary>
		/// This method does the work of combining the
previously supported method that
		/// took an exception, now allowing arbitrary params and
supporting formatting.
		/// 
		/// This makes it convenient to do something like: 
		/// 
		///		log.Debug( "message with params {0} and
{1}", "param1", "param2" )
		///		
		/// without needing to use 
		/// 
		///		log.Debug( string.Format( "message with
params {0} and {1}", "param1", "param2" ) )
		///		
		/// </summary>
		/// <param name="level"></param>
		/// <param name="message"></param>
		/// <param name="parameters"></param>
		private void LogFormatted( Level level, object message,
params object[] parameters )
		{
			//
			// Optimization to avoid string-building penalty
if logging is not enabled
			// at the requested level
			//
			if( false == this.Logger.IsEnabledFor( level ) )
			{
				return;
			}

			if( null == parameters  ||  0 ==
parameters.Length )
			{
				this.Logger.Log( this.m_fullName, level,
message, null );
				return;
			}

			if( 1 == parameters.Length )
			{
				System.Exception ex = parameters[0] as
System.Exception;
				if( null != ex )
				{
					if( false ==
MessageRequiresFormatting( message ) )
					{
						this.Logger.Log(
this.m_fullName, level, message, ex );
						return;
					}

					// String contains formatting
specifier.  Fall through to allow in-line formatting
				}
			}

			string formatString = CreateFormatString(
message );
			string formatted = string.Format( formatString,
parameters );
			this.Logger.Log(this.m_fullName, level,
formatted, null);
		}

		private bool MessageRequiresFormatting( object message )
		{
			// If either of these conditions occurs, we can
log the string directly
			// and return without needing to call
string.Format
			//
			// 1)  The message is not a string
			// 2)  The message is a string, but doesn't
contain embedded formatting characters {0}

			string messageAsString = message as string;
			if( null == messageAsString  ||  false ==
ContainsFormattingSpecification( messageAsString ) )
			{
				return false;
			}
			return true;
		}

		private bool ContainsFormattingSpecification( string
message )
		{
			if( null != message )
			{
				if( -1 != message.IndexOf( "{0" ) )
				{
					return true;
				}
			}
			return false;
		}

		/// <summary>
		/// The format string is passed to <see
cref="string.Format"/> 
		/// along with the input parameters to have it render a
display
		/// message
		/// </summary>
		/// <param name="message"></param>
		/// <returns></returns>
		private string CreateFormatString(object message)
		{
			string formatString = message as string;
			if( null == formatString )
			{
				if( null == message )
				{
					formatString = "";
				}
				else
				{
					formatString =
message.ToString();
				}
			}
			return formatString;
		}

		#region NUnit Tests
#if NUNIT_TESTS
		/// <summary>
		/// NUnit Tests
		/// </summary>
		[TestFixture] public class TestMyLogImpl : ILogger
		{
			string toString;
			ArrayList events;

			#region MessageEvent class
			/// <summary>
			/// Class to record logging event details when
the event occurs
			/// </summary>
			private class MessageEvent
			{
				public log4net.spi.Level level;
				public object message;
				public System.Exception exception;

				/// <summary>
				/// Constructor
				/// </summary>
				/// <param name="level"></param>
				/// <param name="message"></param>
				public MessageEvent( log4net.spi.Level
level, object message ) : this( level, message, null )
				{}

				/// <summary>
				/// Constructor
				/// </summary>
				/// <param name="level"></param>
				/// <param name="message"></param>
				/// <param name="exception"></param>
				public MessageEvent( log4net.spi.Level
level, object message, System.Exception exception )
				{
					this.level = level;
					this.message = message;
					this.exception = exception;
				}
			}
			#endregion

			private void RecordMessage( log4net.spi.Level
level, object message )
			{
				events.Add( new MessageEvent( level,
message ) );				
			}

			private void RecordMessage( log4net.spi.Level
level, object message, System.Exception ex )
			{
				events.Add( new MessageEvent( level,
message, ex ) );				
			}

			#region ILogger Members

			public void Log(LoggingEvent logEvent)
			{
				throw new NotImplementedException();
			}

			public void Log(string callerFullName, Level
level, object message, Exception t)
			{
				RecordMessage( level, message, t );
			}

			public bool IsEnabledFor(Level level)
			{
				return true;
			}

			/// <summary>
			/// Fake the name for now
			/// </summary>
			public string Name 
			{ 
				get
				{
					return "";
				}
			}

			/// <summary>
			/// Fake repository for now
			/// </summary>
			public log4net.Repository.ILoggerRepository
Repository 
			{ 
				get
				{
					return null;
				}
			}

			#endregion

			/// <summary>
			/// Allows us to create a test object that is
non-string based and
			/// supply a string in the ToString method call
			/// </summary>
			/// <returns></returns>
			public override string ToString()
			{
				return toString;
			}

			/// <summary>
			/// Does per-test initialization
			/// </summary>
			[SetUp] public void SetUp()
			{
				events = new ArrayList();
				toString = String.Empty;
			}

			/// <summary>
			/// Tests 3 cases - 
			/// 
			/// 1)  Legacy, method call with message and no
params, like log.Debug( message );
			/// 2)  Legacy, method call with message and
exception, like log.Debug( message, exception );
			/// 3)  New, method call with formatted string
and variable number of parameters, log.Debug( messageToFormat, param1,
param2 );
			/// </summary>
			[Test] public void TestDebugWithParams()
			{
				MyLogImpl wrapper = new MyLogImpl( this
);
				Exception ex1 = new
ApplicationException( "using Debug" );
				this.toString = "ToString test message";

				wrapper.Debug( "my {0} message, logged
as Debug", "one-param" );
				wrapper.Debug( "single-param message,
logged as Debug with exception and no formatting", ex1 );
				wrapper.Debug( "my {0} message, logged
as Debug with params {1} and {2}", "multi-param", 3, 2.1 );
				wrapper.Debug( "my {0} message, logged
as Debug with exception {1}", "multi-param", ex1 );
				wrapper.Debug( "single-param message,
logged as Debug with exception {0} and formatting", ex1 );
				wrapper.Debug( "single-param message,
logged as Debug with non-string param {0} and formatting", this );
				wrapper.Debug( null, "param1", "param2"
);

				Assert.Equals( 7, events.Count );

				// Fallback - Existing method should be
called for single message (no params)
				VerifyMessageEvent( (MessageEvent)
events[0], log4net.spi.Level.DEBUG, "my one-param message, logged as
Debug" );
				
				// Fallback - this one should be
backward compatible with existing methods that call Debug( object,
exception )
				VerifyMessageEvent( (MessageEvent)
events[1], log4net.spi.Level.DEBUG, "single-param message, logged as
Debug with exception and no formatting", ex1 );

				// New - methods with params should be
supported now
				VerifyMessageEvent( (MessageEvent)
events[2], log4net.spi.Level.DEBUG, "my multi-param message, logged as
Debug with params 3 and 2.1" );
				VerifyMessageEvent( (MessageEvent)
events[3], log4net.spi.Level.DEBUG, string.Format( "my multi-param
message, logged as Debug with exception {0}", ex1 ) );
				VerifyMessageEvent( (MessageEvent)
events[4], log4net.spi.Level.DEBUG, string.Format( "single-param
message, logged as Debug with exception {0} and formatting", ex1 ) );
				VerifyMessageEvent( (MessageEvent)
events[5], log4net.spi.Level.DEBUG, string.Format( "single-param
message, logged as Debug with non-string param {0} and formatting", this
) );
				VerifyMessageEvent( (MessageEvent)
events[6], log4net.spi.Level.DEBUG, "" );
			}

			/// <summary>
			/// Similar to the Debug test, but checks to see
that the Info method is called instead
			/// 
			/// Note this doesn't cover all the possible
test scenarios in the Debug method test,
			/// just some quick tests to make sure the right
method is getting called
			/// </summary>
			[Test] public void TestInfoWithParams()
			{
				MyLogImpl wrapper = new MyLogImpl( this
);
				Exception ex1 = new
ApplicationException( "using Info" );

				wrapper.Info( "my {0} message, logged as
Info", "one-param" );
				wrapper.Info( "my {0} message, logged as
Info with params {1} and {2}", "multi-param", 3, 2.1 );
				wrapper.Info( "my {0} message, logged as
Info with exception {1}", "multi-param", ex1 );
				wrapper.Info( "single-param message,
logged as Info with exception {0} and formatting", ex1 );
				wrapper.Info( "single-param message,
logged as Info with exception and no formatting", ex1 );

				Assert.Equals( 5, events.Count );

				// Fallback - Existing method should be
called for single message (no params)
				VerifyMessageEvent( (MessageEvent)
events[0], log4net.spi.Level.INFO, "my one-param message, logged as
Info" );
				
				// Fallback - this one should be
backward compatible with existing methods that call Debug( object,
exception )
				VerifyMessageEvent( (MessageEvent)
events[4], log4net.spi.Level.INFO, "single-param message, logged as Info
with exception and no formatting", ex1 );

				// New - methods with params should be
supported now
				VerifyMessageEvent( (MessageEvent)
events[1], log4net.spi.Level.INFO, "my multi-param message, logged as
Info with params 3 and 2.1" );
				VerifyMessageEvent( (MessageEvent)
events[2], log4net.spi.Level.INFO, string.Format( "my multi-param
message, logged as Info with exception {0}", ex1 ) );
				VerifyMessageEvent( (MessageEvent)
events[3], log4net.spi.Level.INFO, string.Format( "single-param message,
logged as Info with exception {0} and formatting", ex1 ) );
			}

			/// <summary>
			/// Tests that when the message string has the
opening brace { but no closing brace,
			/// an exception is thrown.  This is because the
format method expects {0} as a 
			/// parameter.
			/// </summary>
			[ExpectedException( typeof( FormatException ) )]
			[Test] public void
TestDebugWithParams_InvalidFormatThrowsException()
			{
				MyLogImpl wrapper = new MyLogImpl( this
);
				Exception ex1 = new
ApplicationException( "using Debug" );
				wrapper.Debug( "my { message, logged as
Debug", "one-param" );
			}

			/// <summary>
			/// Assumes exception is not present
			/// </summary>
			/// <param name="messageEvent"></param>
			/// <param name="expectedLevel"></param>
			/// <param name="expectedMessage"></param>
			private void VerifyMessageEvent( MessageEvent
messageEvent, log4net.spi.Level expectedLevel, string expectedMessage,
Exception expectedException )
			{
				Assert.Equals( expectedLevel,
messageEvent.level );
				Assert.Equals( expectedMessage,
messageEvent.message );
				Assert.Same( expectedException,
messageEvent.exception );
			}

			/// <summary>
			/// Assumes exception is not present
			/// </summary>
			/// <param name="messageEvent"></param>
			/// <param name="expectedLevel"></param>
			/// <param name="expectedMessage"></param>
			private void VerifyMessageEvent( MessageEvent
messageEvent, log4net.spi.Level expectedLevel, string expectedMessage )
			{
				Assert.Equals( expectedLevel,
messageEvent.level );
				Assert.Equals( expectedMessage,
messageEvent.message );
				Assert.Null( messageEvent.exception );
			}
		}
#endif
		#endregion
	}
}