yv01p/Umbraco-CMS
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Updates async logging to a newer format

Browse Source
This commit is contained in:
Shannon
2015-07-01 13:46:11 +02:00
parent 56315768e9
commit 44943e367f
15 changed files with 1391 additions and 419 deletions
Download Patch File Download Diff File Expand all files Collapse all files

0
src/Umbraco.Core/Logging/AppDomainTokenFormatter.cs → src/Umbraco.Core/Logging/AppDomainTokenConverter.cs
View File

105
src/Umbraco.Core/Logging/AsyncForwardingAppenderBase.cs Normal file
View File

@@ -0,0 +1,105 @@
using System;
using log4net.Appender;
using log4net.Core;
using log4net.Util;
namespace Umbraco.Core.Logging
{
/// <remarks>
/// Based on https://github.com/cjbhaines/Log4Net.Async
/// </remarks>
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); }
}
/// <summary>
/// The logger name that will be used for logging internal errors.
/// </summary>
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
}
}

480
src/Umbraco.Core/Logging/AsynchronousRollingFileAppender.cs
View File

@@ -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
{
/// <summary>
/// Based on code by Chris Haines http://cjbhaines.wordpress.com/2012/02/13/asynchronous-log4net-appenders/
/// <summary>
/// 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/
/// </summary>
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<LoggingEvent> _pendingAppends;
private int _queueSizeLimit = 1000;
private bool _shuttingDown;
private RingBuffer<LoggingEvent> 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<LoggingEvent>(QueueSizeLimit);
pendingAppends.BufferOverflow += OnBufferOverflow;
StartAppendTask();
}
public override void ActivateOptions()
{
base.ActivateOptions();
_pendingAppends = new RingBuffer<LoggingEvent>(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<T>
{
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<T> : IQueue<T>
{
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<T>
{
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<object, EventArgs> BufferOverflow;
public event Action<object, EventArgs> 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;
}
}
}
}

17
src/Umbraco.Core/Logging/LoggingEventContext.cs Normal file
View File

@@ -0,0 +1,17 @@
using log4net.Core;
namespace Umbraco.Core.Logging
{
/// <remarks>
/// Based on https://github.com/cjbhaines/Log4Net.Async
/// </remarks>
internal class LoggingEventContext
{
public LoggingEventContext(LoggingEvent loggingEvent)
{
LoggingEvent = loggingEvent;
}
public LoggingEvent LoggingEvent { get; set; }
}
}

31
src/Umbraco.Core/Logging/LoggingEventHelper.cs Normal file
View File

@@ -0,0 +1,31 @@
using System;
using log4net.Core;
namespace Umbraco.Core.Logging
{
/// <remarks>
/// Based on https://github.com/cjbhaines/Log4Net.Async
/// </remarks>
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;
}
}
}

307
src/Umbraco.Core/Logging/ParallelForwardingAppender.cs Normal file
View File

@@ -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
{
/// <summary>
/// An asynchronous appender based on <see cref="BlockingCollection{T}"/>
/// </summary>
/// <remarks>
/// Based on https://github.com/cjbhaines/Log4Net.Async
/// </remarks>
public class ParallelForwardingAppender : AsyncForwardingAppenderBase, IDisposable
{
#region Private Members
private const int DefaultBufferSize = 1000;
private BlockingCollection<LoggingEventContext> _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
/// <summary>
/// Gets or sets the number of LoggingEvents that will be buffered. Set to null for unlimited.
/// </summary>
public override int? BufferSize
{
get { return _bufferSize; }
set { _bufferSize = value; }
}
public int BufferEntryCount
{
get
{
if (_loggingEvents == null) return 0;
return _loggingEvents.Count;
}
}
/// <summary>
/// Gets or sets the time period in which the system will wait for appenders to flush before canceling the background task.
/// </summary>
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<LoggingEventContext>(BufferSize.Value);
}
else
{
//No limit on the number of events.
_loggingEvents = new BlockingCollection<LoggingEventContext>();
}
//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
/// <summary>
/// Iterates over a BlockingCollection containing LoggingEvents.
/// </summary>
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
}
}

6
src/Umbraco.Core/Umbraco.Core.csproj
View File

@@ -331,8 +331,12 @@
<Compile Include="HttpContextExtensions.cs" />
<Compile Include="IApplicationEventHandler.cs" />
<Compile Include="IDisposeOnRequestEnd.cs" />
<Compile Include="Logging\AsyncForwardingAppenderBase.cs" />
<Compile Include="Logging\LoggingEventContext.cs" />
<Compile Include="Logging\LoggingEventHelper.cs" />
<Compile Include="Logging\OwinLogger.cs" />
<Compile Include="Logging\OwinLoggerFactory.cs" />
<Compile Include="Logging\ParallelForwardingAppender.cs" />
<Compile Include="Manifest\GridEditorConverter.cs" />
<Compile Include="Models\AuditItem.cs" />
<Compile Include="Models\AuditType.cs" />
@@ -431,7 +435,7 @@
<Compile Include="IO\ResizedImage.cs" />
<Compile Include="IO\UmbracoMediaFile.cs" />
<Compile Include="Logging\DebugDiagnosticsLogger.cs" />
<Compile Include="Logging\AppDomainTokenFormatter.cs" />
<Compile Include="Logging\AppDomainTokenConverter.cs" />
<Compile Include="Logging\LoggerExtensions.cs" />
<Compile Include="Logging\LoggerResolver.cs" />
<Compile Include="Logging\ProfilingLogger.cs" />

173
src/Umbraco.Tests/AsynchronousRollingFileAppenderTests.cs
View File

@@ -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<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");
}
}
}

166
src/Umbraco.Tests/Logging/AsyncRollingFileAppenderTest.cs Normal file
View File

@@ -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<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");
}
}
}

22
src/Umbraco.Tests/Logging/DebugAppender.cs Normal file
View File

@@ -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);
}
}
}

324
src/Umbraco.Tests/Logging/ParallelForwarderTest.cs Normal file
View File

@@ -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<IAppender>();
asyncForwardingAppender.AddAppender(badAppender.Object);
badAppender
.Setup(ba => ba.DoAppend(It.IsAny<LoggingEvent>()))
.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<LoggingEvent>()), 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);
}
}
}

147
src/Umbraco.Tests/Logging/RingBufferTest.cs Normal file
View File

@@ -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<string> ringBuffer = new RingBuffer<string>(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<string> ringBuffer = new RingBuffer<string>(1000);
Stopwatch ringWatch = new Stopwatch();
List<Task> ringTasks = new List<Task>();
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<string> ringBuffer = new RingBuffer<string>(1000);
Stopwatch ringWatch = new Stopwatch();
List<Task> ringTasks = new List<Task>();
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<object> queue = new RingBuffer<object>(limit);
// Act
queue.Enqueue(object1);
queue.Enqueue(object2);
queue.Enqueue(object3);
// Assert
object value;
queue.TryDequeue(out value);
Assert.That(value, Is.EqualTo(object2));
queue.TryDequeue(out value);
Assert.That(value, Is.EqualTo(object3));
queue.TryDequeue(out value);
Assert.That(value, Is.Null);
}
}
}

5
src/Umbraco.Tests/Umbraco.Tests.csproj
View File

@@ -177,6 +177,9 @@
<Compile Include="AttemptTests.cs" />
<Compile Include="Cache\CacheRefresherTests.cs" />
<Compile Include="Cache\DeepCloneRuntimeCacheProviderTests.cs" />
<Compile Include="Logging\AsyncRollingFileAppenderTest.cs" />
<Compile Include="Logging\DebugAppender.cs" />
<Compile Include="Logging\ParallelForwarderTest.cs" />
<Compile Include="Persistence\Repositories\AuditRepositoryTest.cs" />
<Compile Include="Persistence\Repositories\DomainRepositoryTest.cs" />
<Compile Include="Persistence\Repositories\PublicAccessRepositoryTest.cs" />
@@ -445,7 +448,7 @@
<Compile Include="PublishedContent\PublishedContentMoreTests.cs" />
<Compile Include="Publishing\PublishingStrategyTests.cs" />
<Compile Include="Resolvers\ActionsResolverTests.cs" />
<Compile Include="AsynchronousRollingFileAppenderTests.cs" />
<Compile Include="Logging\RingBufferTest.cs" />
<Compile Include="TestHelpers\BaseUmbracoConfigurationTest.cs" />
<Compile Include="TestHelpers\DatabaseTestBehaviorAttribute.cs" />
<Compile Include="TestHelpers\Entities\MockedMember.cs" />

8
src/Umbraco.Web.UI/config/log4net.Release.config
View File

@@ -5,8 +5,8 @@
<priority value="Info"/>
<appender-ref ref="AsynchronousLog4NetAppender" />
</root>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.AsynchronousRollingFileAppender, Umbraco.Core">
<appender name="rollingFile" type="log4net.Appender.RollingFileAppender">
<file value="App_Data\Logs\UmbracoTraceLog.txt" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<appendToFile value="true" />
@@ -18,6 +18,10 @@
<encoding value="utf-8" />
</appender>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.ParallelForwardingAppender,Umbraco.Core">
<appender-ref ref="rollingFile" />
</appender>
<!--Here you can change the way logging works for certain namespaces -->
<logger name="NHibernate">

19
src/Umbraco.Web.UI/config/log4net.config
View File

@@ -6,8 +6,7 @@
<appender-ref ref="AsynchronousLog4NetAppender" />
</root>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.AsynchronousRollingFileAppender, Umbraco.Core">
<appender name="rollingFile" type="log4net.Appender.RollingFileAppender">
<file value="App_Data\Logs\UmbracoTraceLog.txt" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<appendToFile value="true" />
@@ -19,6 +18,22 @@
<encoding value="utf-8" />
</appender>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.ParallelForwardingAppender,Umbraco.Core">
<appender-ref ref="rollingFile" />
</appender>
<!--<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.AsynchronousRollingFileAppender, Umbraco.Core">
<file value="App_Data\Logs\UmbracoTraceLog.txt" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
<appendToFile value="true" />
<rollingStyle value="Date" />
<maximumFileSize value="5MB" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
</layout>
<encoding value="utf-8" />
</appender>-->
<!--Here you can change the way logging works for certain namespaces -->
<logger name="NHibernate">