diff --git a/src/Umbraco.Core/Logging/AppDomainTokenFormatter.cs b/src/Umbraco.Core/Logging/AppDomainTokenConverter.cs
similarity index 100%
rename from src/Umbraco.Core/Logging/AppDomainTokenFormatter.cs
rename to src/Umbraco.Core/Logging/AppDomainTokenConverter.cs
diff --git a/src/Umbraco.Core/Logging/AsyncForwardingAppenderBase.cs b/src/Umbraco.Core/Logging/AsyncForwardingAppenderBase.cs
new file mode 100644
index 0000000000..74a1de81f4
--- /dev/null
+++ b/src/Umbraco.Core/Logging/AsyncForwardingAppenderBase.cs
@@ -0,0 +1,105 @@
+using System;
+using log4net.Appender;
+using log4net.Core;
+using log4net.Util;
+
+namespace Umbraco.Core.Logging
+{
+ ///
+ /// Based on https://github.com/cjbhaines/Log4Net.Async
+ ///
+ public abstract class AsyncForwardingAppenderBase : ForwardingAppender
+ {
+ #region Private Members
+
+ private const FixFlags DefaultFixFlags = FixFlags.Partial;
+ private FixFlags _fixFlags = DefaultFixFlags;
+ private LoggingEventHelper _loggingEventHelper;
+
+ #endregion Private Members
+
+ #region Properties
+
+ public FixFlags Fix
+ {
+ get { return _fixFlags; }
+ set { SetFixFlags(value); }
+ }
+
+ ///
+ /// The logger name that will be used for logging internal errors.
+ ///
+ protected abstract string InternalLoggerName { get; }
+
+ public abstract int? BufferSize { get; set; }
+
+ #endregion Properties
+
+ public override void ActivateOptions()
+ {
+ base.ActivateOptions();
+ _loggingEventHelper = new LoggingEventHelper(InternalLoggerName, DefaultFixFlags);
+ InitializeAppenders();
+ }
+
+ #region Appender Management
+
+ public override void AddAppender(IAppender newAppender)
+ {
+ base.AddAppender(newAppender);
+ SetAppenderFixFlags(newAppender);
+ }
+
+ private void SetFixFlags(FixFlags newFixFlags)
+ {
+ if (newFixFlags != _fixFlags)
+ {
+ _loggingEventHelper.Fix = newFixFlags;
+ _fixFlags = newFixFlags;
+ InitializeAppenders();
+ }
+ }
+
+ private void InitializeAppenders()
+ {
+ foreach (var appender in Appenders)
+ {
+ SetAppenderFixFlags(appender);
+ }
+ }
+
+ private void SetAppenderFixFlags(IAppender appender)
+ {
+ var bufferingAppender = appender as BufferingAppenderSkeleton;
+ if (bufferingAppender != null)
+ {
+ bufferingAppender.Fix = Fix;
+ }
+ }
+
+ #endregion Appender Management
+
+ #region Forwarding
+
+ protected void ForwardInternalError(string message, Exception exception, Type thisType)
+ {
+ LogLog.Error(thisType, message, exception);
+ var loggingEvent = _loggingEventHelper.CreateLoggingEvent(Level.Error, message, exception);
+ ForwardLoggingEvent(loggingEvent, thisType);
+ }
+
+ protected void ForwardLoggingEvent(LoggingEvent loggingEvent, Type thisType)
+ {
+ try
+ {
+ base.Append(loggingEvent);
+ }
+ catch (Exception exception)
+ {
+ LogLog.Error(thisType, "Unable to forward logging event", exception);
+ }
+ }
+
+ #endregion Forwarding
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Core/Logging/AsynchronousRollingFileAppender.cs b/src/Umbraco.Core/Logging/AsynchronousRollingFileAppender.cs
index 56d04c8426..cb58ebbfaa 100644
--- a/src/Umbraco.Core/Logging/AsynchronousRollingFileAppender.cs
+++ b/src/Umbraco.Core/Logging/AsynchronousRollingFileAppender.cs
@@ -1,276 +1,276 @@
+using log4net.Core;
+using log4net.Util;
using System;
+using System.Runtime.Remoting.Messaging;
using System.Security.Principal;
using System.Threading;
using System.Threading.Tasks;
using log4net.Appender;
-using log4net.Core;
-using log4net.Util;
namespace Umbraco.Core.Logging
{
- ///
- /// Based on code by Chris Haines http://cjbhaines.wordpress.com/2012/02/13/asynchronous-log4net-appenders/
+ ///
+ /// Based on https://github.com/cjbhaines/Log4Net.Async
+ /// which is based on code by Chris Haines http://cjbhaines.wordpress.com/2012/02/13/asynchronous-log4net-appenders/
///
public class AsynchronousRollingFileAppender : RollingFileAppender
{
- private readonly ManualResetEvent _manualResetEvent;
- private int _bufferOverflowCounter;
- private bool _forceStop;
- private bool _hasFinished;
- private DateTime _lastLoggedBufferOverflow;
- private bool _logBufferOverflow;
- private RingBuffer _pendingAppends;
- private int _queueSizeLimit = 1000;
- private bool _shuttingDown;
+ private RingBuffer pendingAppends;
+ private readonly ManualResetEvent manualResetEvent;
+ private bool shuttingDown;
+ private bool hasFinished;
+ private bool forceStop;
+ private bool logBufferOverflow;
+ private int bufferOverflowCounter;
+ private DateTime lastLoggedBufferOverflow;
+ private int queueSizeLimit = 1000;
+ public int QueueSizeLimit
+ {
+ get
+ {
+ return queueSizeLimit;
+ }
+ set
+ {
+ queueSizeLimit = value;
+ }
+ }
- public AsynchronousRollingFileAppender()
- {
- _manualResetEvent = new ManualResetEvent(false);
- }
+ public AsynchronousRollingFileAppender()
+ {
+ manualResetEvent = new ManualResetEvent(false);
+ }
- public int QueueSizeLimit
- {
- get { return _queueSizeLimit; }
- set { _queueSizeLimit = value; }
- }
+ public override void ActivateOptions()
+ {
+ base.ActivateOptions();
+ pendingAppends = new RingBuffer(QueueSizeLimit);
+ pendingAppends.BufferOverflow += OnBufferOverflow;
+ StartAppendTask();
+ }
- public override void ActivateOptions()
- {
- base.ActivateOptions();
- _pendingAppends = new RingBuffer(QueueSizeLimit);
- _pendingAppends.BufferOverflow += OnBufferOverflow;
- StartAppendTask();
- }
+ protected override void Append(LoggingEvent[] loggingEvents)
+ {
+ Array.ForEach(loggingEvents, Append);
+ }
- protected override void Append(LoggingEvent[] loggingEvents)
- {
- Array.ForEach(loggingEvents, Append);
- }
+ protected override void Append(LoggingEvent loggingEvent)
+ {
+ if (FilterEvent(loggingEvent))
+ {
+ pendingAppends.Enqueue(loggingEvent);
+ }
+ }
- protected override void Append(LoggingEvent loggingEvent)
- {
- if (FilterEvent(loggingEvent))
- {
- _pendingAppends.Enqueue(loggingEvent);
- }
- }
+ protected override void OnClose()
+ {
+ shuttingDown = true;
+ manualResetEvent.WaitOne(TimeSpan.FromSeconds(5));
- protected override void OnClose()
- {
- _shuttingDown = true;
- _manualResetEvent.WaitOne(TimeSpan.FromSeconds(5));
+ if (!hasFinished)
+ {
+ forceStop = true;
+ base.Append(new LoggingEvent(new LoggingEventData
+ {
+ Level = Level.Error,
+ Message = "Unable to clear out the AsyncRollingFileAppender buffer in the allotted time, forcing a shutdown",
+ TimeStamp = DateTime.UtcNow,
+ Identity = "",
+ ExceptionString = "",
+ UserName = WindowsIdentity.GetCurrent() != null ? WindowsIdentity.GetCurrent().Name : "",
+ Domain = AppDomain.CurrentDomain.FriendlyName,
+ ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
+ LocationInfo = new LocationInfo(this.GetType().Name, "OnClose", "AsyncRollingFileAppender.cs", "75"),
+ LoggerName = this.GetType().FullName,
+ Properties = new PropertiesDictionary(),
+ })
+ );
+ }
- if (!_hasFinished)
- {
- _forceStop = true;
- var windowsIdentity = WindowsIdentity.GetCurrent();
+ base.OnClose();
+ }
- var logEvent = new LoggingEvent(new LoggingEventData
- {
- Level = global::log4net.Core.Level.Error,
- Message =
- "Unable to clear out the AsynchronousRollingFileAppender buffer in the allotted time, forcing a shutdown",
- TimeStamp = DateTime.UtcNow,
- Identity = "",
- ExceptionString = "",
- UserName = windowsIdentity != null ? windowsIdentity.Name : "",
- Domain = AppDomain.CurrentDomain.FriendlyName,
- ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
- LocationInfo =
- new LocationInfo(this.GetType().Name, "OnClose", "AsynchronousRollingFileAppender.cs", "59"),
- LoggerName = this.GetType().FullName,
- Properties = new PropertiesDictionary(),
- });
+ private void StartAppendTask()
+ {
+ if (!shuttingDown)
+ {
+ Task appendTask = new Task(AppendLoggingEvents, TaskCreationOptions.LongRunning);
+ appendTask.LogErrors(LogAppenderError).ContinueWith(x => StartAppendTask()).LogErrors(LogAppenderError);
+ appendTask.Start();
+ }
+ }
- if (this.DateTimeStrategy != null)
- {
- base.Append(logEvent);
- }
- }
+ private void LogAppenderError(string logMessage, Exception exception)
+ {
+ base.Append(new LoggingEvent(new LoggingEventData
+ {
+ Level = Level.Error,
+ Message = "Appender exception: " + logMessage,
+ TimeStamp = DateTime.UtcNow,
+ Identity = "",
+ ExceptionString = exception.ToString(),
+ UserName = WindowsIdentity.GetCurrent() != null ? WindowsIdentity.GetCurrent().Name : "",
+ Domain = AppDomain.CurrentDomain.FriendlyName,
+ ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
+ LocationInfo = new LocationInfo(this.GetType().Name, "LogAppenderError", "AsyncRollingFileAppender.cs", "152"),
+ LoggerName = this.GetType().FullName,
+ Properties = new PropertiesDictionary(),
+ }));
+ }
- base.OnClose();
- }
+ private void AppendLoggingEvents()
+ {
+ LoggingEvent loggingEventToAppend;
+ while (!shuttingDown)
+ {
+ if (logBufferOverflow)
+ {
+ LogBufferOverflowError();
+ logBufferOverflow = false;
+ bufferOverflowCounter = 0;
+ lastLoggedBufferOverflow = DateTime.UtcNow;
+ }
- private void StartAppendTask()
- {
- if (!_shuttingDown)
- {
- Task appendTask = new Task(AppendLoggingEvents, TaskCreationOptions.LongRunning);
- appendTask.LogErrors(LogAppenderError).ContinueWith(x => StartAppendTask()).LogErrors(LogAppenderError);
- appendTask.Start();
- }
- }
+ while (!pendingAppends.TryDequeue(out loggingEventToAppend))
+ {
+ Thread.Sleep(10);
+ if (shuttingDown)
+ {
+ break;
+ }
+ }
+ if (loggingEventToAppend == null)
+ {
+ continue;
+ }
- private void LogAppenderError(string logMessage, Exception exception)
- {
- var windowsIdentity = WindowsIdentity.GetCurrent();
- base.Append(new LoggingEvent(new LoggingEventData
- {
- Level = Level.Error,
- Message = "Appender exception: " + logMessage,
- TimeStamp = DateTime.UtcNow,
- Identity = "",
- ExceptionString = exception.ToString(),
- UserName = windowsIdentity != null ? windowsIdentity.Name : "",
- Domain = AppDomain.CurrentDomain.FriendlyName,
- ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
- LocationInfo =
- new LocationInfo(this.GetType().Name,
- "LogAppenderError",
- "AsynchronousRollingFileAppender.cs",
- "100"),
- LoggerName = this.GetType().FullName,
- Properties = new PropertiesDictionary(),
- }));
- }
+ try
+ {
+ base.Append(loggingEventToAppend);
+ }
+ catch
+ {
+ }
+ }
- private void AppendLoggingEvents()
- {
- LoggingEvent loggingEventToAppend;
- while (!_shuttingDown)
- {
- if (_logBufferOverflow)
- {
- LogBufferOverflowError();
- _logBufferOverflow = false;
- _bufferOverflowCounter = 0;
- _lastLoggedBufferOverflow = DateTime.UtcNow;
- }
+ while (pendingAppends.TryDequeue(out loggingEventToAppend) && !forceStop)
+ {
+ try
+ {
+ base.Append(loggingEventToAppend);
+ }
+ catch
+ {
+ }
+ }
+ hasFinished = true;
+ manualResetEvent.Set();
+ }
- while (!_pendingAppends.TryDequeue(out loggingEventToAppend))
- {
- Thread.Sleep(10);
- if (_shuttingDown)
- {
- break;
- }
- }
- if (loggingEventToAppend == null)
- {
- continue;
- }
+ private void LogBufferOverflowError()
+ {
+ base.Append(new LoggingEvent(new LoggingEventData
+ {
+ Level = Level.Error,
+ Message = string.Format("Buffer overflow. {0} logging events have been lost in the last 30 seconds. [QueueSizeLimit: {1}]", bufferOverflowCounter, QueueSizeLimit),
+ TimeStamp = DateTime.UtcNow,
+ Identity = "",
+ ExceptionString = "",
+ UserName = WindowsIdentity.GetCurrent() != null ? WindowsIdentity.GetCurrent().Name : "",
+ Domain = AppDomain.CurrentDomain.FriendlyName,
+ ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
+ LocationInfo = new LocationInfo(this.GetType().Name, "LogBufferOverflowError", "AsyncRollingFileAppender.cs", "152"),
+ LoggerName = this.GetType().FullName,
+ Properties = new PropertiesDictionary(),
+ }));
+ }
- try
- {
- base.Append(loggingEventToAppend);
- }
- catch
- {
- }
- }
+ private void OnBufferOverflow(object sender, EventArgs eventArgs)
+ {
+ bufferOverflowCounter++;
+ if (logBufferOverflow == false)
+ {
+ if (lastLoggedBufferOverflow < DateTime.UtcNow.AddSeconds(-30))
+ {
+ logBufferOverflow = true;
+ }
+ }
+ }
+ }
- while (_pendingAppends.TryDequeue(out loggingEventToAppend) && !_forceStop)
- {
- try
- {
- base.Append(loggingEventToAppend);
- }
- catch
- {
- }
- }
- _hasFinished = true;
- _manualResetEvent.Set();
- }
+ internal interface IQueue
+ {
+ void Enqueue(T item);
+ bool TryDequeue(out T ret);
+ }
- private void LogBufferOverflowError()
- {
- var windowsIdentity = WindowsIdentity.GetCurrent();
- base.Append(new LoggingEvent(new LoggingEventData
- {
- Level = Level.Error,
- Message =
- string.Format(
- "Buffer overflow. {0} logging events have been lost in the last 30 seconds. [QueueSizeLimit: {1}]",
- _bufferOverflowCounter,
- QueueSizeLimit),
- TimeStamp = DateTime.UtcNow,
- Identity = "",
- ExceptionString = "",
- UserName = windowsIdentity != null ? windowsIdentity.Name : "",
- Domain = AppDomain.CurrentDomain.FriendlyName,
- ThreadName = Thread.CurrentThread.ManagedThreadId.ToString(),
- LocationInfo =
- new LocationInfo(this.GetType().Name,
- "LogBufferOverflowError",
- "AsynchronousRollingFileAppender.cs",
- "172"),
- LoggerName = this.GetType().FullName,
- Properties = new PropertiesDictionary(),
- }));
- }
+ internal class RingBuffer : IQueue
+ {
+ private readonly object lockObject = new object();
+ private readonly T[] buffer;
+ private readonly int size;
+ private int readIndex = 0;
+ private int writeIndex = 0;
+ private bool bufferFull = false;
- private void OnBufferOverflow(object sender, EventArgs eventArgs)
- {
- _bufferOverflowCounter++;
- if (_logBufferOverflow == false)
- {
- if (_lastLoggedBufferOverflow < DateTime.UtcNow.AddSeconds(-30))
- {
- _logBufferOverflow = true;
- }
- }
- }
+ public int Size { get { return size; } }
- private class RingBuffer
- {
- private readonly object _lockObject = new object();
- private readonly T[] _buffer;
- private readonly int _size;
- private int _readIndex = 0;
- private int _writeIndex = 0;
- private bool _bufferFull = false;
+ public event Action BufferOverflow;
- public event Action BufferOverflow;
+ public RingBuffer(int size)
+ {
+ this.size = size;
+ buffer = new T[size];
+ }
- public RingBuffer(int size)
- {
- this._size = size;
- _buffer = new T[size];
- }
+ public void Enqueue(T item)
+ {
+ var bufferWasFull = false;
+ lock (lockObject)
+ {
+ buffer[writeIndex] = item;
+ writeIndex = (++writeIndex) % size;
+ if (bufferFull)
+ {
+ bufferWasFull = true;
+ readIndex = writeIndex;
+ }
+ else if (writeIndex == readIndex)
+ {
+ bufferFull = true;
+ }
+ }
- public void Enqueue(T item)
- {
- lock (_lockObject)
- {
- _buffer[_writeIndex] = item;
- _writeIndex = (++_writeIndex) % _size;
- if (_bufferFull)
- {
- if (BufferOverflow != null)
- {
- BufferOverflow(this, EventArgs.Empty);
- }
- _readIndex = _writeIndex;
- }
- else if (_writeIndex == _readIndex)
- {
- _bufferFull = true;
- }
- }
- }
+ if (bufferWasFull)
+ {
+ if (BufferOverflow != null)
+ {
+ BufferOverflow(this, EventArgs.Empty);
+ }
+ }
+ }
- public bool TryDequeue(out T ret)
- {
- if (_readIndex == _writeIndex && !_bufferFull)
- {
- ret = default(T);
- return false;
- }
- lock (_lockObject)
- {
- if (_readIndex == _writeIndex && !_bufferFull)
- {
- ret = default(T);
- return false;
- }
+ public bool TryDequeue(out T ret)
+ {
+ if (readIndex == writeIndex && !bufferFull)
+ {
+ ret = default(T);
+ return false;
+ }
+ lock (lockObject)
+ {
+ if (readIndex == writeIndex && !bufferFull)
+ {
+ ret = default(T);
+ return false;
+ }
- ret = _buffer[_readIndex];
- _readIndex = (++_readIndex) % _size;
- _bufferFull = false;
- return true;
- }
- }
- }
- }
+ ret = buffer[readIndex];
+ buffer[readIndex] = default(T);
+ readIndex = (++readIndex) % size;
+ bufferFull = false;
+ return true;
+ }
+ }
+ }
}
\ No newline at end of file
diff --git a/src/Umbraco.Core/Logging/LoggingEventContext.cs b/src/Umbraco.Core/Logging/LoggingEventContext.cs
new file mode 100644
index 0000000000..159af4266b
--- /dev/null
+++ b/src/Umbraco.Core/Logging/LoggingEventContext.cs
@@ -0,0 +1,17 @@
+using log4net.Core;
+
+namespace Umbraco.Core.Logging
+{
+ ///
+ /// Based on https://github.com/cjbhaines/Log4Net.Async
+ ///
+ internal class LoggingEventContext
+ {
+ public LoggingEventContext(LoggingEvent loggingEvent)
+ {
+ LoggingEvent = loggingEvent;
+ }
+
+ public LoggingEvent LoggingEvent { get; set; }
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Core/Logging/LoggingEventHelper.cs b/src/Umbraco.Core/Logging/LoggingEventHelper.cs
new file mode 100644
index 0000000000..c788e115f2
--- /dev/null
+++ b/src/Umbraco.Core/Logging/LoggingEventHelper.cs
@@ -0,0 +1,31 @@
+using System;
+using log4net.Core;
+
+namespace Umbraco.Core.Logging
+{
+ ///
+ /// Based on https://github.com/cjbhaines/Log4Net.Async
+ ///
+ internal class LoggingEventHelper
+ {
+ // needs to be a seperate class so that location is determined correctly by log4net when required
+
+ private static readonly Type HelperType = typeof(LoggingEventHelper);
+ private readonly string loggerName;
+
+ public FixFlags Fix { get; set; }
+
+ public LoggingEventHelper(string loggerName, FixFlags fix)
+ {
+ this.loggerName = loggerName;
+ Fix = fix;
+ }
+
+ public LoggingEvent CreateLoggingEvent(Level level, string message, Exception exception)
+ {
+ var loggingEvent = new LoggingEvent(HelperType, null, loggerName, level, message, exception);
+ loggingEvent.Fix = Fix;
+ return loggingEvent;
+ }
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Core/Logging/ParallelForwardingAppender.cs b/src/Umbraco.Core/Logging/ParallelForwardingAppender.cs
new file mode 100644
index 0000000000..92c4f7589b
--- /dev/null
+++ b/src/Umbraco.Core/Logging/ParallelForwardingAppender.cs
@@ -0,0 +1,307 @@
+using System;
+using System.Collections.Concurrent;
+using System.Threading;
+using System.Threading.Tasks;
+using log4net.Core;
+using log4net.Util;
+
+namespace Umbraco.Core.Logging
+{
+ ///
+ /// An asynchronous appender based on
+ ///
+ ///
+ /// Based on https://github.com/cjbhaines/Log4Net.Async
+ ///
+ public class ParallelForwardingAppender : AsyncForwardingAppenderBase, IDisposable
+ {
+ #region Private Members
+
+ private const int DefaultBufferSize = 1000;
+ private BlockingCollection _loggingEvents;
+ private CancellationTokenSource _loggingCancelationTokenSource;
+ private CancellationToken _loggingCancelationToken;
+ private Task _loggingTask;
+ private Double _shutdownFlushTimeout = 5;
+ private TimeSpan _shutdownFlushTimespan = TimeSpan.FromSeconds(5);
+ private static readonly Type ThisType = typeof(ParallelForwardingAppender);
+ private volatile bool _shutDownRequested;
+ private int? _bufferSize = DefaultBufferSize;
+
+ #endregion Private Members
+
+ #region Properties
+
+ ///
+ /// Gets or sets the number of LoggingEvents that will be buffered. Set to null for unlimited.
+ ///
+ public override int? BufferSize
+ {
+ get { return _bufferSize; }
+ set { _bufferSize = value; }
+ }
+
+ public int BufferEntryCount
+ {
+ get
+ {
+ if (_loggingEvents == null) return 0;
+ return _loggingEvents.Count;
+ }
+ }
+
+ ///
+ /// Gets or sets the time period in which the system will wait for appenders to flush before canceling the background task.
+ ///
+ public Double ShutdownFlushTimeout
+ {
+ get
+ {
+ return _shutdownFlushTimeout;
+ }
+ set
+ {
+ _shutdownFlushTimeout = value;
+ }
+ }
+
+ protected override string InternalLoggerName
+ {
+ get { return "ParallelForwardingAppender"; }
+ }
+
+ #endregion Properties
+
+ #region Startup
+
+ public override void ActivateOptions()
+ {
+ base.ActivateOptions();
+ _shutdownFlushTimespan = TimeSpan.FromSeconds(_shutdownFlushTimeout);
+ StartForwarding();
+ }
+
+ private void StartForwarding()
+ {
+ if (_shutDownRequested)
+ {
+ return;
+ }
+ //Create a collection which will block the thread and wait for new entries
+ //if the collection is empty
+ if (BufferSize.HasValue && BufferSize > 0)
+ {
+ _loggingEvents = new BlockingCollection(BufferSize.Value);
+ }
+ else
+ {
+ //No limit on the number of events.
+ _loggingEvents = new BlockingCollection();
+ }
+ //The cancellation token is used to cancel a running task gracefully.
+ _loggingCancelationTokenSource = new CancellationTokenSource();
+ _loggingCancelationToken = _loggingCancelationTokenSource.Token;
+ _loggingTask = new Task(SubscriberLoop, _loggingCancelationToken);
+ _loggingTask.Start();
+ }
+
+ #endregion Startup
+
+ #region Shutdown
+
+ private void CompleteSubscriberTask()
+ {
+ _shutDownRequested = true;
+ if (_loggingEvents == null || _loggingEvents.IsAddingCompleted)
+ {
+ return;
+ }
+ //Don't allow more entries to be added.
+ _loggingEvents.CompleteAdding();
+ //Allow some time to flush
+ Thread.Sleep(_shutdownFlushTimespan);
+ if (!_loggingTask.IsCompleted && !_loggingCancelationToken.IsCancellationRequested)
+ {
+ _loggingCancelationTokenSource.Cancel();
+ //Wait here so that the error logging messages do not get into a random order.
+ //Don't pass the cancellation token because we are not interested
+ //in catching the OperationCanceledException that results.
+ _loggingTask.Wait();
+ }
+ if (!_loggingEvents.IsCompleted)
+ {
+ ForwardInternalError("The buffer was not able to be flushed before timeout occurred.", null, ThisType);
+ }
+ }
+
+ protected override void OnClose()
+ {
+ CompleteSubscriberTask();
+ base.OnClose();
+ }
+
+ #endregion Shutdown
+
+ #region Appending
+
+ protected override void Append(LoggingEvent loggingEvent)
+ {
+ if (_loggingEvents == null || _loggingEvents.IsAddingCompleted || loggingEvent == null)
+ {
+ return;
+ }
+
+ loggingEvent.Fix = Fix;
+ //In the case where blocking on a full collection, and the task is subsequently completed, the cancellation token
+ //will prevent the entry from attempting to add to the completed collection which would result in an exception.
+ _loggingEvents.Add(new LoggingEventContext(loggingEvent), _loggingCancelationToken);
+ }
+
+ protected override void Append(LoggingEvent[] loggingEvents)
+ {
+ if (_loggingEvents == null || _loggingEvents.IsAddingCompleted || loggingEvents == null)
+ {
+ return;
+ }
+
+ foreach (var loggingEvent in loggingEvents)
+ {
+ Append(loggingEvent);
+ }
+ }
+
+ #endregion Appending
+
+ #region Forwarding
+
+ ///
+ /// Iterates over a BlockingCollection containing LoggingEvents.
+ ///
+ private void SubscriberLoop()
+ {
+ Thread.CurrentThread.Name = String.Format("{0} ParallelForwardingAppender Subscriber Task", Name);
+ //The task will continue in a blocking loop until
+ //the queue is marked as adding completed, or the task is canceled.
+ try
+ {
+ //This call blocks until an item is available or until adding is completed
+ foreach (var entry in _loggingEvents.GetConsumingEnumerable(_loggingCancelationToken))
+ {
+ ForwardLoggingEvent(entry.LoggingEvent, ThisType);
+ }
+ }
+ catch (OperationCanceledException ex)
+ {
+ //The thread was canceled before all entries could be forwarded and the collection completed.
+ ForwardInternalError("Subscriber task was canceled before completion.", ex, ThisType);
+ //Cancellation is called in the CompleteSubscriberTask so don't call that again.
+ }
+ catch (ThreadAbortException ex)
+ {
+ //Thread abort may occur on domain unload.
+ ForwardInternalError("Subscriber task was aborted.", ex, ThisType);
+ //Cannot recover from a thread abort so complete the task.
+ CompleteSubscriberTask();
+ //The exception is swallowed because we don't want the client application
+ //to halt due to a logging issue.
+ }
+ catch (Exception ex)
+ {
+ //On exception, try to log the exception
+ ForwardInternalError("Subscriber task error in forwarding loop.", ex, ThisType);
+ //Any error in the loop is going to be some sort of extenuating circumstance from which we
+ //probably cannot recover anyway. Complete subscribing.
+ CompleteSubscriberTask();
+ }
+ }
+
+ #endregion Forwarding
+
+ #region IDisposable Implementation
+
+ private bool _disposed = false;
+
+ //Implement IDisposable.
+ public void Dispose()
+ {
+ Dispose(true);
+ GC.SuppressFinalize(this);
+ }
+
+ protected virtual void Dispose(bool disposing)
+ {
+ if (!_disposed)
+ {
+ if (disposing)
+ {
+ if (_loggingTask != null)
+ {
+ if (!(_loggingTask.IsCanceled || _loggingTask.IsCompleted || _loggingTask.IsFaulted))
+ {
+ try
+ {
+ CompleteSubscriberTask();
+ }
+ catch (Exception ex)
+ {
+ LogLog.Error(ThisType, "Exception Completing Subscriber Task in Dispose Method", ex);
+ }
+ }
+ try
+ {
+ _loggingTask.Dispose();
+ }
+ catch (Exception ex)
+ {
+ LogLog.Error(ThisType, "Exception Disposing Logging Task", ex);
+ }
+ finally
+ {
+ _loggingTask = null;
+ }
+ }
+ if (_loggingEvents != null)
+ {
+ try
+ {
+ _loggingEvents.Dispose();
+ }
+ catch (Exception ex)
+ {
+ LogLog.Error(ThisType, "Exception Disposing BlockingCollection", ex);
+ }
+ finally
+ {
+ _loggingEvents = null;
+ }
+ }
+ if (_loggingCancelationTokenSource != null)
+ {
+ try
+ {
+ _loggingCancelationTokenSource.Dispose();
+ }
+ catch (Exception ex)
+ {
+ LogLog.Error(ThisType, "Exception Disposing CancellationTokenSource", ex);
+ }
+ finally
+ {
+ _loggingCancelationTokenSource = null;
+ }
+ }
+ }
+ _disposed = true;
+ }
+ }
+
+ // Use C# destructor syntax for finalization code.
+ ~ParallelForwardingAppender()
+ {
+ // Simply call Dispose(false).
+ Dispose(false);
+ }
+
+ #endregion IDisposable Implementation
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Core/Umbraco.Core.csproj b/src/Umbraco.Core/Umbraco.Core.csproj
index 7c71015702..007d12500b 100644
--- a/src/Umbraco.Core/Umbraco.Core.csproj
+++ b/src/Umbraco.Core/Umbraco.Core.csproj
@@ -331,8 +331,12 @@
+
+
+
+
@@ -431,7 +435,7 @@
-
+
diff --git a/src/Umbraco.Tests/AsynchronousRollingFileAppenderTests.cs b/src/Umbraco.Tests/AsynchronousRollingFileAppenderTests.cs
deleted file mode 100644
index 2f1a8d99d3..0000000000
--- a/src/Umbraco.Tests/AsynchronousRollingFileAppenderTests.cs
+++ /dev/null
@@ -1,173 +0,0 @@
-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 Umbraco.Tests.TestHelpers;
-using log4net;
-using log4net.Config;
-using log4net.Core;
-using log4net.Layout;
-using log4net.Repository;
-
-namespace Umbraco.Tests
-{
- //Ignore this test, it fails sometimes on the build server - pretty sure it's a threading issue with this test class
- [Ignore]
- [TestFixture]
- public class AsynchronousRollingFileAppenderTests
- {
- 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/Logging/AsyncRollingFileAppenderTest.cs b/src/Umbraco.Tests/Logging/AsyncRollingFileAppenderTest.cs
new file mode 100644
index 0000000000..37323a67d5
--- /dev/null
+++ b/src/Umbraco.Tests/Logging/AsyncRollingFileAppenderTest.cs
@@ -0,0 +1,166 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Linq;
+using System.Threading;
+using log4net;
+using log4net.Config;
+using log4net.Core;
+using log4net.Layout;
+using log4net.Repository;
+using NUnit.Framework;
+using Umbraco.Core;
+using Umbraco.Core.Logging;
+
+namespace Umbraco.Tests.Logging
+{
+ [TestFixture]
+ public class AsyncRollingFileAppenderTest
+ {
+ private const string ErrorMessage = "TEST ERROR MESSAGE";
+ private const 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()
+ {
+ 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/Logging/DebugAppender.cs b/src/Umbraco.Tests/Logging/DebugAppender.cs
new file mode 100644
index 0000000000..c1a1523349
--- /dev/null
+++ b/src/Umbraco.Tests/Logging/DebugAppender.cs
@@ -0,0 +1,22 @@
+using System;
+using System.Threading;
+using log4net.Appender;
+using log4net.Core;
+
+namespace Umbraco.Tests.Logging
+{
+ internal class DebugAppender : MemoryAppender
+ {
+ public TimeSpan AppendDelay { get; set; }
+ public int LoggedEventCount { get { return m_eventsList.Count; } }
+
+ protected override void Append(LoggingEvent loggingEvent)
+ {
+ if (AppendDelay > TimeSpan.Zero)
+ {
+ Thread.Sleep(AppendDelay);
+ }
+ base.Append(loggingEvent);
+ }
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Tests/Logging/ParallelForwarderTest.cs b/src/Umbraco.Tests/Logging/ParallelForwarderTest.cs
new file mode 100644
index 0000000000..fffc28fe1f
--- /dev/null
+++ b/src/Umbraco.Tests/Logging/ParallelForwarderTest.cs
@@ -0,0 +1,324 @@
+using System;
+using System.Diagnostics;
+using System.Security.Principal;
+using System.Threading;
+using log4net;
+using log4net.Appender;
+using log4net.Config;
+using log4net.Core;
+using log4net.Filter;
+using log4net.Repository;
+using Moq;
+using NUnit.Framework;
+using Umbraco.Core.Logging;
+
+namespace Umbraco.Tests.Logging
+{
+ [TestFixture]
+ public class ParallelForwarderTest : IDisposable
+ {
+ private ParallelForwardingAppender asyncForwardingAppender;
+ private DebugAppender debugAppender;
+ private ILoggerRepository repository;
+ private ILog log;
+
+ [SetUp]
+ public void TestFixtureSetUp()
+ {
+ debugAppender = new DebugAppender();
+ debugAppender.ActivateOptions();
+
+ asyncForwardingAppender = new ParallelForwardingAppender();
+ asyncForwardingAppender.AddAppender(debugAppender);
+ asyncForwardingAppender.ActivateOptions();
+
+ repository = LogManager.CreateRepository(Guid.NewGuid().ToString());
+ BasicConfigurator.Configure(repository, asyncForwardingAppender);
+
+ log = LogManager.GetLogger(repository.Name, "TestLogger");
+ }
+
+ [TearDown]
+ public void TearDown()
+ {
+ LogManager.Shutdown();
+ }
+
+ [Test]
+ public void CanHandleNullLoggingEvent()
+ {
+ // Arrange
+
+ // Act
+ asyncForwardingAppender.DoAppend((LoggingEvent)null);
+ log.Info("SusequentMessage");
+ asyncForwardingAppender.Close();
+
+ // Assert - should not have had an exception from previous call
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(1), "Expected subsequent message only");
+ Assert.That(debugAppender.GetEvents()[0].MessageObject, Is.EqualTo("SusequentMessage"));
+ }
+
+ [Test]
+ public void CanHandleNullLoggingEvents()
+ {
+ // Arrange
+
+ // Act
+ asyncForwardingAppender.DoAppend((LoggingEvent[])null);
+ log.Info("SusequentMessage");
+ asyncForwardingAppender.Close();
+
+ // Assert - should not have had an exception from previous call
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(1), "Expected subsequent message only");
+ Assert.That(debugAppender.GetEvents()[0].MessageObject, Is.EqualTo("SusequentMessage"));
+ }
+
+ [Test]
+ public void CanHandleAppenderThrowing()
+ {
+ // Arrange
+ var badAppender = new Mock();
+ asyncForwardingAppender.AddAppender(badAppender.Object);
+
+ badAppender
+ .Setup(ba => ba.DoAppend(It.IsAny()))
+ .Throws(new Exception("Bad Appender"));
+ //.Verifiable();
+
+ // Act
+ log.Info("InitialMessage");
+ log.Info("SusequentMessage");
+ asyncForwardingAppender.Close();
+
+ // Assert
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(2));
+ Assert.That(debugAppender.GetEvents()[1].MessageObject, Is.EqualTo("SusequentMessage"));
+ badAppender.Verify(appender => appender.DoAppend(It.IsAny()), Times.Exactly(2));
+ }
+
+ [Test]
+ public void WillLogFastWhenThereIsASlowAppender()
+ {
+ const int testSize = 1000;
+
+ // Arrange
+ debugAppender.AppendDelay = TimeSpan.FromSeconds(10);
+ var watch = new Stopwatch();
+
+ // Act
+ watch.Start();
+ for (int i = 0; i < testSize; i++)
+ {
+ log.Error("Exception");
+ }
+ watch.Stop();
+
+ // Assert
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(0));
+ Assert.That(watch.ElapsedMilliseconds, Is.LessThan(testSize));
+ Console.WriteLine("Logged {0} errors in {1}ms", testSize, watch.ElapsedMilliseconds);
+ }
+
+ [Test]
+ public void WillNotOverflow()
+ {
+ const int testSize = 1000;
+
+ // Arrange
+ debugAppender.AppendDelay = TimeSpan.FromMilliseconds(1);
+ asyncForwardingAppender.BufferSize = 100;
+
+ // Act
+ for (int i = 0; i < testSize; i++)
+ {
+ log.Error("Exception");
+ }
+
+ while (asyncForwardingAppender.BufferEntryCount > 0) ;
+ asyncForwardingAppender.Close();
+
+ // Assert
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(testSize));
+ }
+
+ [Test]
+ public void WillTryToFlushBufferOnShutdown()
+ {
+ const int testSize = 250;
+
+ // Arrange
+ debugAppender.AppendDelay = TimeSpan.FromMilliseconds(1);
+
+ // Act
+ for (int i = 0; i < testSize; i++)
+ {
+ log.Error("Exception");
+ }
+
+ Thread.Sleep(50);
+
+ var numberLoggedBeforeClose = debugAppender.LoggedEventCount;
+ asyncForwardingAppender.Close();
+ var numberLoggedAfterClose = debugAppender.LoggedEventCount;
+
+ // Assert
+ //We can't use specific numbers here because the timing and counts will be different on different systems.
+ Assert.That(numberLoggedBeforeClose, Is.GreaterThan(0), "Some number of Logging events should be logged prior to appender close.");
+ //On some systems, we may not be able to flush all events prior to close, but it is reasonable to assume in this test case
+ //that some events should be logged after close.
+ Assert.That(numberLoggedAfterClose, Is.GreaterThan(numberLoggedBeforeClose), "Some number of LoggingEvents should be logged after close.");
+ Console.WriteLine("Flushed {0} events during shutdown", numberLoggedAfterClose - numberLoggedBeforeClose);
+ }
+
+ [Test, Explicit("Long-running")]
+ public void WillShutdownIfBufferCannotBeFlushedFastEnough()
+ {
+ const int testSize = 250;
+
+ // Arrange
+ debugAppender.AppendDelay = TimeSpan.FromSeconds(1);
+ Stopwatch watch = new Stopwatch();
+
+ // Act
+ for (int i = 0; i < testSize; i++)
+ {
+ log.Error("Exception");
+ }
+
+ Thread.Sleep(TimeSpan.FromSeconds(2));
+ var numberLoggedBeforeClose = debugAppender.LoggedEventCount;
+
+ watch.Start();
+ asyncForwardingAppender.Close();
+ watch.Stop();
+
+ var numberLoggedAfterClose = debugAppender.LoggedEventCount;
+
+ // Assert
+ Assert.That(numberLoggedBeforeClose, Is.GreaterThan(0));
+ Assert.That(numberLoggedAfterClose, Is.GreaterThan(numberLoggedBeforeClose));
+ Assert.That(numberLoggedAfterClose, Is.LessThan(testSize));
+ //We can't assume what the shutdown time will be. It will vary from system to system. Don't test shutdown time.
+ var events = debugAppender.GetEvents();
+ var evnt = events[events.Length - 1];
+ Assert.That(evnt.MessageObject, Is.EqualTo("The buffer was not able to be flushed before timeout occurred."));
+ Console.WriteLine("Flushed {0} events during shutdown which lasted {1}ms", numberLoggedAfterClose - numberLoggedBeforeClose, watch.ElapsedMilliseconds);
+ }
+
+ [Test]
+ public void ThreadContextPropertiesArePreserved()
+ {
+ // Arrange
+ ThreadContext.Properties["TestProperty"] = "My Value";
+ Assert.That(asyncForwardingAppender.Fix & FixFlags.Properties, Is.EqualTo(FixFlags.Properties), "Properties must be fixed if they are to be preserved");
+
+ // Act
+ log.Info("Information");
+ asyncForwardingAppender.Close();
+
+ // Assert
+ var lastLoggedEvent = debugAppender.GetEvents()[0];
+ Assert.That(lastLoggedEvent.Properties["TestProperty"], Is.EqualTo("My Value"));
+ }
+
+ [Test]
+ public void MessagesExcludedByFilterShouldNotBeAppended()
+ {
+ // Arrange
+ var levelFilter =
+ new LevelRangeFilter
+ {
+ LevelMin = Level.Warn,
+ LevelMax = Level.Error,
+ };
+
+ asyncForwardingAppender.AddFilter(levelFilter);
+
+ // Act
+ log.Info("Info");
+ log.Warn("Warn");
+ log.Error("Error");
+ log.Fatal("Fatal");
+
+ asyncForwardingAppender.Close();
+
+ //Assert
+ Assert.That(debugAppender.LoggedEventCount, Is.EqualTo(2));
+ }
+
+ [Test]
+ public void HelperCanGenerateLoggingEventWithAllProperties()
+ {
+ // Arrange
+ var helper = new LoggingEventHelper("TestLoggerName", FixFlags.All);
+ ThreadContext.Properties["MyProperty"] = "MyValue";
+ var exception = new Exception("SomeError");
+
+ var stackFrame = new StackFrame(0);
+ var currentUser = WindowsIdentity.GetCurrent();
+ var loggingTime = DateTime.Now; // Log4Net does not seem to be using UtcNow
+
+ // Act
+ var loggingEvent = helper.CreateLoggingEvent(Level.Emergency, "Who's on live support?", exception);
+ Thread.Sleep(50); // to make sure the time stamp is actually captured
+
+ // Assert
+ Assert.That(loggingEvent.Domain, Is.EqualTo(AppDomain.CurrentDomain.FriendlyName), "Domain");
+ //The identity assigned to new threads is dependent upon AppDomain principal policy.
+ //Background information here:http://www.neovolve.com/post/2010/10/21/Unit-testing-a-workflow-that-relies-on-ThreadCurrentPrincipalIdentityName.aspx
+ //VS2013 does have a principal assigned to new threads in the unit test.
+ //It's probably best not to test that the identity has been set.
+ //Assert.That(loggingEvent.Identity, Is.Empty, "Identity: always empty for some reason");
+ Assert.That(loggingEvent.UserName, Is.EqualTo(currentUser == null ? String.Empty : currentUser.Name), "UserName");
+ Assert.That(loggingEvent.ThreadName, Is.EqualTo(Thread.CurrentThread.Name), "ThreadName");
+
+ Assert.That(loggingEvent.Repository, Is.Null, "Repository: Helper does not have access to this");
+ Assert.That(loggingEvent.LoggerName, Is.EqualTo("TestLoggerName"), "LoggerName");
+
+ Assert.That(loggingEvent.Level, Is.EqualTo(Level.Emergency), "Level");
+ //Raised time to within 10 ms. However, this may not be a valid test. The time is going to vary from system to system. The
+ //tolerance setting here is arbitrary.
+ Assert.That(loggingEvent.TimeStamp, Is.EqualTo(loggingTime).Within(TimeSpan.FromMilliseconds(10)), "TimeStamp");
+ Assert.That(loggingEvent.ExceptionObject, Is.EqualTo(exception), "ExceptionObject");
+ Assert.That(loggingEvent.MessageObject, Is.EqualTo("Who's on live support?"), "MessageObject");
+
+ Assert.That(loggingEvent.LocationInformation.MethodName, Is.EqualTo(stackFrame.GetMethod().Name), "LocationInformation");
+ Assert.That(loggingEvent.Properties["MyProperty"], Is.EqualTo("MyValue"), "Properties");
+ }
+
+ private bool _disposed = false;
+
+ //Implement IDisposable.
+ public void Dispose()
+ {
+ Dispose(true);
+ GC.SuppressFinalize(this);
+ }
+
+ protected virtual void Dispose(bool disposing)
+ {
+ if (!_disposed)
+ {
+ if (disposing)
+ {
+ if (asyncForwardingAppender != null)
+ {
+ asyncForwardingAppender.Dispose();
+ asyncForwardingAppender = null;
+ }
+ }
+ // Free your own state (unmanaged objects).
+ // Set large fields to null.
+ _disposed = true;
+ }
+ }
+
+ // Use C# destructor syntax for finalization code.
+ ~ParallelForwarderTest()
+ {
+ // Simply call Dispose(false).
+ Dispose(false);
+ }
+ }
+}
\ No newline at end of file
diff --git a/src/Umbraco.Tests/Logging/RingBufferTest.cs b/src/Umbraco.Tests/Logging/RingBufferTest.cs
new file mode 100644
index 0000000000..8e80faf8ad
--- /dev/null
+++ b/src/Umbraco.Tests/Logging/RingBufferTest.cs
@@ -0,0 +1,147 @@
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Threading;
+using System.Threading.Tasks;
+using NUnit.Framework;
+using Umbraco.Core.Logging;
+using Umbraco.Tests.TestHelpers;
+
+namespace Umbraco.Tests.Logging
+{
+ [TestFixture]
+ public class RingBufferTest
+ {
+ [Test]
+ public void PerfTest()
+ {
+ RingBuffer ringBuffer = new RingBuffer(1000);
+ Stopwatch ringWatch = new Stopwatch();
+ ringWatch.Start();
+ for (int i = 0; i < 1000000; i++)
+ {
+ ringBuffer.Enqueue("StringOfFun");
+ }
+ ringWatch.Stop();
+
+ Assert.That(ringWatch.ElapsedMilliseconds, Is.LessThan(150));
+ }
+
+ [Test]
+ public void PerfTestThreads()
+ {
+ RingBuffer ringBuffer = new RingBuffer(1000);
+
+ Stopwatch ringWatch = new Stopwatch();
+ List ringTasks = new List();
+ CancellationTokenSource cancelationTokenSource = new CancellationTokenSource();
+ CancellationToken cancelationToken = cancelationTokenSource.Token;
+ for (int t = 0; t < 10; t++)
+ {
+ ringTasks.Add(new Task(() =>
+ {
+ for (int i = 0; i < 1000000; i++)
+ {
+ ringBuffer.Enqueue("StringOfFun");
+ }
+ }, cancelationToken));
+ }
+ ringWatch.Start();
+ ringTasks.ForEach(t => t.Start());
+ var allTasks = ringTasks.ToArray();
+ Task.WaitAny(allTasks);
+ ringWatch.Stop();
+ //Cancel tasks to avoid System.AppDominUnloadException which is caused when the domain is unloaded
+ //and threads created in the domain are not stopped.
+ //Do this before assertions because they may throw an exception causing the thread cancellation to not happen.
+ cancelationTokenSource.Cancel();
+ try
+ {
+ Task.WaitAll(allTasks);
+ }
+ catch (AggregateException)
+ {
+ //Don't care about cancellation Exceptions.
+ }
+ //Tolerance at 500 was too low
+ ringTasks.ForEach(t => t.Dispose());
+ Assert.That(ringWatch.ElapsedMilliseconds, Is.LessThan(1000));
+ }
+
+ [Test]
+ public void PerfTestThreadsWithDequeues()
+ {
+ RingBuffer ringBuffer = new RingBuffer(1000);
+
+ Stopwatch ringWatch = new Stopwatch();
+ List ringTasks = new List();
+ CancellationTokenSource cancelationTokenSource = new CancellationTokenSource();
+ CancellationToken cancelationToken = cancelationTokenSource.Token;
+ for (int t = 0; t < 10; t++)
+ {
+ ringTasks.Add(new Task(() =>
+ {
+ for (int i = 0; i < 1000000; i++)
+ {
+ ringBuffer.Enqueue("StringOfFun");
+ }
+ }, cancelationToken));
+ }
+ for (int t = 0; t < 10; t++)
+ {
+ ringTasks.Add(new Task(() =>
+ {
+ for (int i = 0; i < 1000000; i++)
+ {
+ string foo;
+ ringBuffer.TryDequeue(out foo);
+ }
+ }));
+ }
+ ringWatch.Start();
+ ringTasks.ForEach(t => t.Start());
+ var allTasks = ringTasks.ToArray();
+ Task.WaitAny(allTasks);
+ ringWatch.Stop();
+ //Cancel tasks to avoid System.AppDominUnloadException which is caused when the domain is unloaded
+ //and threads created in the domain are not stopped.
+ //Do this before assertions because they may throw an exception causing the thread cancellation to not happen.
+ cancelationTokenSource.Cancel();
+ try
+ {
+ Task.WaitAll(allTasks);
+ }
+ catch (AggregateException)
+ {
+ //Don't care about cancellation Exceptions.
+ }
+ ringTasks.ForEach(t => t.Dispose());
+ Assert.That(ringWatch.ElapsedMilliseconds, Is.LessThan(800));
+ }
+
+ [Test]
+ public void WhenRingSizeLimitIsHit_ItemsAreDequeued()
+ {
+ // Arrange
+ const int limit = 2;
+ object object1 = "one";
+ object object2 = "two";
+ object object3 = "three";
+ RingBuffer