Added unit test for custom log file appender, integrated a few more classes from v5 for tracing,

added initial trace logging to application startup which works. Changed the application startup handler
to use new logging, now the system won't bork if the sql db isn't initialized.

src/Umbraco.Core/ApplicationContext.cs

@@ -4,8 +4,7 @@ using System.Diagnostics;
 
 
 namespace Umbraco.Core
-{	
-
+{
 	/// <summary>
     /// the Umbraco Application context
     /// </summary>

src/Umbraco.Core/DisposableObject.cs

@@ -0,0 +1,72 @@
+using System;
+using System.Threading;
+
+namespace Umbraco.Core
+{
+	/// <summary>
+	/// Abstract implementation of logic commonly required to safely handle disposable unmanaged resources.
+	/// </summary>
+	public abstract class DisposableObject : IDisposable
+	{
+		private bool _disposed;
+		private readonly ReaderWriterLockSlim _disposalLocker = new ReaderWriterLockSlim();
+
+		/// <summary>
+		/// Gets a value indicating whether this instance is disposed.
+		/// </summary>
+		/// <value>
+		/// 	<c>true</c> if this instance is disposed; otherwise, <c>false</c>.
+		/// </value>
+		public bool IsDisposed
+		{
+			get { return _disposed; }
+		}
+
+		/// <summary>
+		/// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
+		/// </summary>
+		/// <filterpriority>2</filterpriority>
+		public void Dispose()
+		{
+			Dispose(true);
+
+			// Use SupressFinalize in case a subclass of this type implements a finalizer.
+			GC.SuppressFinalize(this);
+		}
+
+		~DisposableObject()
+		{
+			// Run dispose but let the class know it was due to the finalizer running.
+			Dispose(false);
+		}
+
+		protected virtual void Dispose(bool disposing)
+		{
+			// Only operate if we haven't already disposed
+			if (IsDisposed || !disposing) return;
+
+			using (new WriteLock(_disposalLocker))
+			{
+				// Check again now we're inside the lock
+				if (IsDisposed) return;
+
+				// Call to actually release resources. This method is only
+				// kept separate so that the entire disposal logic can be used as a VS snippet
+				DisposeResources();
+
+				// Indicate that the instance has been disposed.
+				_disposed = true;
+			}
+		}
+
+		/// <summary>
+		/// Handles the disposal of resources. Derived from abstract class <see cref="DisposableObject"/> which handles common required locking logic.
+		/// </summary>
+		protected abstract void DisposeResources();
+
+		protected virtual void DisposeUnmanagedResources()
+		{
+
+		}
+	}
+}

src/Umbraco.Core/DisposableTimer.cs

@@ -0,0 +1,63 @@
+using System;
+using System.Diagnostics;
+using Umbraco.Core.Logging;
+
+namespace Umbraco.Core
+{
+	/// <summary>
+	/// Starts the timer and invokes a  callback upon disposal. Provides a simple way of timing an operation by wrapping it in a <code>using</code> (C#) statement.
+	/// </summary>
+	/// <example>
+	/// <code>
+	/// Console.WriteLine("Testing Stopwatchdisposable, should be 567:");
+	//  using (var timer = new DisposableTimer(result => Console.WriteLine("Took {0}ms", result)))
+	//  {
+	//      Thread.Sleep(567);
+	//  }
+	/// </code>
+	/// </example>
+	public class DisposableTimer : DisposableObject
+	{
+		private readonly Stopwatch _stopwatch = Stopwatch.StartNew();
+		private readonly Action<long> _callback;
+
+		protected DisposableTimer(Action<long> callback)
+		{
+			_callback = callback;
+		}
+
+		public Stopwatch Stopwatch
+		{
+			get { return _stopwatch; }
+		}
+
+		/// <summary>
+		/// Starts the timer and invokes the specified callback upon disposal.
+		/// </summary>
+		/// <param name="callback">The callback.</param>
+		/// <returns></returns>
+		public static DisposableTimer Start(Action<long> callback)
+		{
+			return new DisposableTimer(callback);
+		}
+
+		public static DisposableTimer TraceDuration<T>(string startMessage, string completeMessage)
+		{
+			return TraceDuration(typeof(T), startMessage, completeMessage);
+		}
+
+		public static DisposableTimer TraceDuration(Type loggerType, string startMessage, string completeMessage)
+		{
+			LogHelper.Info(loggerType, () => startMessage);
+			return new DisposableTimer(x => LogHelper.Info(loggerType, () => completeMessage + " (took " + x + "ms)"));
+		}
+
+		/// <summary>
+		/// Handles the disposal of resources. Derived from abstract class <see cref="DisposableObject"/> which handles common required locking logic.
+		/// </summary>
+		protected override void DisposeResources()
+		{
+			_callback.Invoke(Stopwatch.ElapsedMilliseconds);
+		}
+	}
+}

src/Umbraco.Core/IntExtensions.cs

@@ -0,0 +1,20 @@
+using System;
+
+namespace Umbraco.Core
+{
+	public static class IntExtensions
+	{
+		/// <summary>
+		/// Does something 'x' amount of times
+		/// </summary>
+		/// <param name="n"></param>
+		/// <param name="action"></param>
+		public static void Times(this int n, Action<int> action)
+		{
+			for (int i = 0; i < n; i++)
+			{
+				action(i);
+			}
+		}
+	}
+}

src/Umbraco.Core/Umbraco.Core.csproj

@@ -51,7 +51,10 @@
     <Compile Include="ApplicationContext.cs" />
     <Compile Include="Configuration\GlobalSettings.cs" />
     <Compile Include="Configuration\UmbracoSettings.cs" />
+    <Compile Include="DisposableObject.cs" />
+    <Compile Include="DisposableTimer.cs" />
     <Compile Include="ExpressionHelper.cs" />
+    <Compile Include="IntExtensions.cs" />
     <Compile Include="IO\FileSecurityException.cs" />
     <Compile Include="IO\IOHelper.cs" />
     <Compile Include="IO\SystemDirectories.cs" />

src/Umbraco.Core/XmlHelper.cs

@@ -4,7 +4,7 @@ using Umbraco.Core.IO;
 
 namespace Umbraco.Core
 {
-    /// <summary>
+	/// <summary>
 	/// The XmlHelper class contains general helper methods for working with xml in umbraco.
     /// </summary>
     internal class XmlHelper

src/Umbraco.Tests/AsynchronousRollingFileAppenderTest.cs

@@ -0,0 +1,170 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Threading;
+using NUnit.Framework;
+using Umbraco.Core;
+using Umbraco.Core.Logging;
+using log4net;
+using log4net.Config;
+using log4net.Core;
+using log4net.Layout;
+using log4net.Repository;
+
+namespace Umbraco.Tests
+{
+	[TestFixture]
+	public class AsynchronousRollingFileAppenderTest
+	{
+		private const string ErrorMessage = "TEST ERROR MESSAGE";
+		private string _fileFolderPath = @"c:\LogTesting\";
+		private readonly Level _errorLevel = Level.Error;
+		private AsynchronousRollingFileAppender _appender;
+		private ILoggerRepository _rep;
+		private Guid _fileGuid;
+
+
+
+		private string GetFilePath()
+		{
+			return string.Format("{0}{1}.log", _fileFolderPath, _fileGuid);
+		}
+
+		[SetUp]
+		public void SetUp()
+		{
+			_fileFolderPath = TestHelper.MapPathForTest("~/LogTesting/");
+
+			_fileGuid = Guid.NewGuid();
+			if (File.Exists(GetFilePath()))
+			{
+				File.Delete(GetFilePath());
+			}
+
+			_appender = new AsynchronousRollingFileAppender();
+			_appender.Threshold = _errorLevel;
+			_appender.File = GetFilePath();
+			_appender.Layout = new PatternLayout("%d|%-5level|%logger| %message %exception%n");
+			_appender.StaticLogFileName = true;
+			_appender.AppendToFile = true;
+			_appender.ActivateOptions();
+
+			_rep = LogManager.CreateRepository(Guid.NewGuid().ToString());
+			BasicConfigurator.Configure(_rep, _appender);
+		}
+
+		[TearDown]
+		public void TearDown()
+		{
+			_rep.Shutdown();
+			if (File.Exists(GetFilePath()))
+			{
+				File.Delete(GetFilePath());
+			}
+		}
+
+		[TestFixtureTearDown]
+		public void FixtureTearDown()
+		{
+			foreach (string file in Directory.GetFiles(_fileFolderPath))
+			{
+				try
+				{
+					File.Delete(file);
+				}
+				catch { }
+			}
+		}
+
+		private void ReleaseFileLocks()
+		{
+			_rep.Shutdown();
+			_appender.Close();
+		}
+
+		[Test]
+		public void CanWriteToFile()
+		{
+			// Arrange
+			ILog log = LogManager.GetLogger(_rep.Name, "CanWriteToDatabase");
+
+			// Act
+			log.Error(ErrorMessage);
+			Thread.Sleep(200); // let background thread finish
+
+			// Assert
+			ReleaseFileLocks();
+			Assert.That(File.Exists(GetFilePath()), Is.True);
+			IEnumerable<string> readLines = File.ReadLines(GetFilePath());
+			Assert.That(readLines.Count(), Is.GreaterThanOrEqualTo(1));
+		}
+
+		[Test]
+		public void ReturnsQuicklyAfterLogging100Messages()
+		{
+			// Arrange
+			ILog log = LogManager.GetLogger(_rep.Name, "ReturnsQuicklyAfterLogging100Messages");
+
+			// Act
+			DateTime startTime = DateTime.UtcNow;
+			100.Times(i => log.Error(ErrorMessage));
+			DateTime endTime = DateTime.UtcNow;
+
+			// Give background thread time to finish
+			Thread.Sleep(500);
+
+			// Assert
+			ReleaseFileLocks();
+			Assert.That(endTime - startTime, Is.LessThan(TimeSpan.FromMilliseconds(100)));
+			Assert.That(File.Exists(GetFilePath()), Is.True);
+			IEnumerable<string> readLines = File.ReadLines(GetFilePath());
+			Assert.That(readLines.Count(), Is.GreaterThanOrEqualTo(100));
+		}
+
+		[Test]
+		public void CanLogAtleast1000MessagesASecond()
+		{
+			// Arrange
+			ILog log = LogManager.GetLogger(_rep.Name, "CanLogAtLeast1000MessagesASecond");
+
+			int logCount = 0;
+			bool logging = true;
+			bool logsCounted = false;
+
+			var logTimer = new Timer(s =>
+				{
+					logging = false;
+
+					if (File.Exists(GetFilePath()))
+					{
+						ReleaseFileLocks();
+						IEnumerable<string> readLines = File.ReadLines(GetFilePath());
+						logCount = readLines.Count();
+					}
+					logsCounted = true;
+				}, null, TimeSpan.FromSeconds(3), TimeSpan.FromMilliseconds(-1));
+
+			// Act
+			DateTime startTime = DateTime.UtcNow;
+			while (logging)
+			{
+				log.Error(ErrorMessage);
+			}
+			TimeSpan testDuration = DateTime.UtcNow - startTime;
+
+			while (!logsCounted)
+			{
+				Thread.Sleep(1);
+			}
+
+			logTimer.Dispose();
+
+			// Assert
+			var logsPerSecond = logCount / testDuration.TotalSeconds;
+
+			Console.WriteLine("{0} messages logged in {1}s => {2}/s", logCount, testDuration.TotalSeconds, logsPerSecond);
+			Assert.That(logsPerSecond, Is.GreaterThan(1000), "Must log at least 1000 messages per second");
+		}
+	}
+}

src/Umbraco.Tests/Umbraco.Tests.csproj

@@ -31,6 +31,9 @@
     <WarningLevel>4</WarningLevel>
   </PropertyGroup>
   <ItemGroup>
+    <Reference Include="log4net, Version=1.2.11.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a, processorArchitecture=MSIL">
+      <HintPath>..\packages\log4net.2.0.0\lib\net40-full\log4net.dll</HintPath>
+    </Reference>
     <Reference Include="nunit.framework">
       <HintPath>..\packages\NUnit.2.6.0.12054\lib\nunit.framework.dll</HintPath>
     </Reference>
@@ -46,6 +49,7 @@
     <Reference Include="System.Xml" />
   </ItemGroup>
   <ItemGroup>
+    <Compile Include="AsynchronousRollingFileAppenderTest.cs" />
     <Compile Include="BusinessLogic\ApplicationTest.cs" />
     <Compile Include="BusinessLogic\ApplicationTreeTest.cs" />
     <Compile Include="BusinessLogic\BaseTest.cs" />

src/Umbraco.Tests/packages.config

@@ -1,4 +1,5 @@
 <?xml version="1.0" encoding="utf-8"?>
 <packages>
+  <package id="log4net" version="2.0.0" targetFramework="net40" />
   <package id="NUnit" version="2.6.0.12054" targetFramework="net40" />
 </packages>

src/Umbraco.Web/UmbracoApplication.cs

@@ -27,35 +27,36 @@ namespace Umbraco.Web
 		/// <param name="e"></param>
 		protected void Application_Start(object sender, EventArgs e)
 		{
-			Trace.TraceInformation("Initialize AppDomain");
+			using (DisposableTimer.TraceDuration<UmbracoApplication>(
+				"Umbraco application starting", 
+				"Umbraco application startup complete"))
+			{
+				// Backwards compatibility - set the path and URL type for ClientDependency 1.5.1 [LK]
+				ClientDependency.Core.CompositeFiles.Providers.XmlFileMapper.FileMapVirtualFolder = "~/App_Data/TEMP/ClientDependency";
+				ClientDependency.Core.CompositeFiles.Providers.BaseCompositeFileProcessingProvider.UrlTypeDefault = ClientDependency.Core.CompositeFiles.Providers.CompositeUrlType.Base64QueryStrings;
 
-			// Backwards compatibility - set the path and URL type for ClientDependency 1.5.1 [LK]
-			ClientDependency.Core.CompositeFiles.Providers.XmlFileMapper.FileMapVirtualFolder = "~/App_Data/TEMP/ClientDependency";
-			ClientDependency.Core.CompositeFiles.Providers.BaseCompositeFileProcessingProvider.UrlTypeDefault = ClientDependency.Core.CompositeFiles.Providers.CompositeUrlType.Base64QueryStrings;
-
-			//create the ApplicationContext
-			ApplicationContext.Current = new ApplicationContext()
+				//create the ApplicationContext
+				ApplicationContext.Current = new ApplicationContext()
 				{
 					IsReady = true	// fixme
 				};
 
-			//find and initialize the application startup handlers
-			ApplicationStartupHandler.RegisterHandlers();
+				//find and initialize the application startup handlers
+				ApplicationStartupHandler.RegisterHandlers();
 
-			// create the resolvers
-			DocumentLookupsResolver.Current = new DocumentLookupsResolver(
-				PluginTypeResolver.Current.ResolveLookups(), 
-				new DefaultLastChanceLookup());
-			RoutesCacheResolver.Current = new RoutesCacheResolver(new DefaultRoutesCache());
+				// create the resolvers
+				DocumentLookupsResolver.Current = new DocumentLookupsResolver(
+					PluginTypeResolver.Current.ResolveLookups(),
+					new DefaultLastChanceLookup());
+				RoutesCacheResolver.Current = new RoutesCacheResolver(new DefaultRoutesCache());
 
-			OnApplicationStarting(sender, e);
+				OnApplicationStarting(sender, e);
 
-			//all resolvers are now frozen and cannot be modified
-			Umbraco.Core.Resolving.Resolution.Freeze();
+				//all resolvers are now frozen and cannot be modified
+				Umbraco.Core.Resolving.Resolution.Freeze();
 
-			OnApplicationStarted(sender, e);
-
-			Trace.TraceInformation("AppDomain is initialized");
+				OnApplicationStarted(sender, e);
+			}
 		}
 
 		/// <summary>

src/umbraco.businesslogic/ApplicationStartupHandler.cs

@@ -5,6 +5,7 @@ using System.Text;
 using System.Threading;
 using System.Web;
 using Umbraco.Core;
+using Umbraco.Core.Logging;
 using umbraco.BusinessLogic;
 using umbraco.BusinessLogic.Utils;
 using umbraco.interfaces;
@@ -41,16 +42,10 @@ namespace umbraco.businesslogic
 														t.FullName);
 				}
 				catch (Exception ee)
-				{
-					//TODO: Fix logging because if this fails here, the app pool wont startup!
-					try
-					{
-						Log.Add(LogTypes.Error, -1, "Error loading application startup handler: " + ee.ToString());
-					}
-					catch
-					{
-						//swallowed... see above comment
-					}
+				{					
+					LogHelper.Error<ApplicationStartupHandler>(
+						string.Format("Error loading application startup handler: {0}", ee.ToString()), 
+						ee);					
 				}
 			}
         }