diff --git a/src/Umbraco.Core/ApplicationContext.cs b/src/Umbraco.Core/ApplicationContext.cs index db50c4e853..37ff9b388b 100644 --- a/src/Umbraco.Core/ApplicationContext.cs +++ b/src/Umbraco.Core/ApplicationContext.cs @@ -4,8 +4,7 @@ using System.Diagnostics; namespace Umbraco.Core -{ - +{ /// /// the Umbraco Application context /// diff --git a/src/Umbraco.Core/DisposableObject.cs b/src/Umbraco.Core/DisposableObject.cs new file mode 100644 index 0000000000..f054b53c98 --- /dev/null +++ b/src/Umbraco.Core/DisposableObject.cs @@ -0,0 +1,72 @@ +using System; +using System.Threading; + +namespace Umbraco.Core +{ + /// + /// Abstract implementation of logic commonly required to safely handle disposable unmanaged resources. + /// + public abstract class DisposableObject : IDisposable + { + private bool _disposed; + private readonly ReaderWriterLockSlim _disposalLocker = new ReaderWriterLockSlim(); + + /// + /// Gets a value indicating whether this instance is disposed. + /// + /// + /// true if this instance is disposed; otherwise, false. + /// + public bool IsDisposed + { + get { return _disposed; } + } + + /// + /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources. + /// + /// 2 + 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; + } + } + + /// + /// Handles the disposal of resources. Derived from abstract class which handles common required locking logic. + /// + protected abstract void DisposeResources(); + + protected virtual void DisposeUnmanagedResources() + { + + } + } +} \ No newline at end of file diff --git a/src/Umbraco.Core/DisposableTimer.cs b/src/Umbraco.Core/DisposableTimer.cs new file mode 100644 index 0000000000..2b9dd6a273 --- /dev/null +++ b/src/Umbraco.Core/DisposableTimer.cs @@ -0,0 +1,63 @@ +using System; +using System.Diagnostics; +using Umbraco.Core.Logging; + +namespace Umbraco.Core +{ + /// + /// Starts the timer and invokes a callback upon disposal. Provides a simple way of timing an operation by wrapping it in a using (C#) statement. + /// + /// + /// + /// Console.WriteLine("Testing Stopwatchdisposable, should be 567:"); + // using (var timer = new DisposableTimer(result => Console.WriteLine("Took {0}ms", result))) + // { + // Thread.Sleep(567); + // } + /// + /// + public class DisposableTimer : DisposableObject + { + private readonly Stopwatch _stopwatch = Stopwatch.StartNew(); + private readonly Action _callback; + + protected DisposableTimer(Action callback) + { + _callback = callback; + } + + public Stopwatch Stopwatch + { + get { return _stopwatch; } + } + + /// + /// Starts the timer and invokes the specified callback upon disposal. + /// + /// The callback. + /// + public static DisposableTimer Start(Action callback) + { + return new DisposableTimer(callback); + } + + public static DisposableTimer TraceDuration(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)")); + } + + /// + /// Handles the disposal of resources. Derived from abstract class which handles common required locking logic. + /// + protected override void DisposeResources() + { + _callback.Invoke(Stopwatch.ElapsedMilliseconds); + } + } +} \ No newline at end of file diff --git a/src/Umbraco.Core/IntExtensions.cs b/src/Umbraco.Core/IntExtensions.cs new file mode 100644 index 0000000000..ffd2cc3a1b --- /dev/null +++ b/src/Umbraco.Core/IntExtensions.cs @@ -0,0 +1,20 @@ +using System; + +namespace Umbraco.Core +{ + public static class IntExtensions + { + /// + /// Does something 'x' amount of times + /// + /// + /// + public static void Times(this int n, Action action) + { + for (int i = 0; i < n; i++) + { + action(i); + } + } + } +} \ No newline at end of file diff --git a/src/Umbraco.Core/Umbraco.Core.csproj b/src/Umbraco.Core/Umbraco.Core.csproj index 5055bdf4d3..ee19019c11 100644 --- a/src/Umbraco.Core/Umbraco.Core.csproj +++ b/src/Umbraco.Core/Umbraco.Core.csproj @@ -51,7 +51,10 @@ + + + diff --git a/src/Umbraco.Core/XmlHelper.cs b/src/Umbraco.Core/XmlHelper.cs index 232bed9611..eb20fb1595 100644 --- a/src/Umbraco.Core/XmlHelper.cs +++ b/src/Umbraco.Core/XmlHelper.cs @@ -4,7 +4,7 @@ using Umbraco.Core.IO; namespace Umbraco.Core { - /// + /// /// The XmlHelper class contains general helper methods for working with xml in umbraco. /// internal class XmlHelper diff --git a/src/Umbraco.Tests/AsynchronousRollingFileAppenderTest.cs b/src/Umbraco.Tests/AsynchronousRollingFileAppenderTest.cs new file mode 100644 index 0000000000..7cf976178a --- /dev/null +++ b/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 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 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 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"); + } + } +} \ No newline at end of file diff --git a/src/Umbraco.Tests/Umbraco.Tests.csproj b/src/Umbraco.Tests/Umbraco.Tests.csproj index 6e02fd0446..e23c094eba 100644 --- a/src/Umbraco.Tests/Umbraco.Tests.csproj +++ b/src/Umbraco.Tests/Umbraco.Tests.csproj @@ -31,6 +31,9 @@ 4 + + ..\packages\log4net.2.0.0\lib\net40-full\log4net.dll + ..\packages\NUnit.2.6.0.12054\lib\nunit.framework.dll @@ -46,6 +49,7 @@ + diff --git a/src/Umbraco.Tests/packages.config b/src/Umbraco.Tests/packages.config index 6158c0a3a2..6c2c554293 100644 --- a/src/Umbraco.Tests/packages.config +++ b/src/Umbraco.Tests/packages.config @@ -1,4 +1,5 @@  + \ No newline at end of file diff --git a/src/Umbraco.Web/UmbracoApplication.cs b/src/Umbraco.Web/UmbracoApplication.cs index 1411ebc693..9396fa90f4 100644 --- a/src/Umbraco.Web/UmbracoApplication.cs +++ b/src/Umbraco.Web/UmbracoApplication.cs @@ -27,35 +27,36 @@ namespace Umbraco.Web /// protected void Application_Start(object sender, EventArgs e) { - Trace.TraceInformation("Initialize AppDomain"); + using (DisposableTimer.TraceDuration( + "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); + } } /// diff --git a/src/umbraco.businesslogic/ApplicationStartupHandler.cs b/src/umbraco.businesslogic/ApplicationStartupHandler.cs index a4dc155a36..7940392b5d 100644 --- a/src/umbraco.businesslogic/ApplicationStartupHandler.cs +++ b/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( + string.Format("Error loading application startup handler: {0}", ee.ToString()), + ee); } } }