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

U4-8432 Update log4net async appender to use the official log4net one

Browse Source
This commit is contained in:
Shannon
2017-04-07 12:07:35 +10:00
parent d582d5c827
commit bc8829ce14
14 changed files with 16 additions and 975 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -16,7 +16,7 @@ namespace Umbraco.Core.Logging
/// This is an old/deprecated logger and has been superceded by ParallelForwardingAppender which is included in Umbraco and
/// also by AsyncForwardingAppender in the Log4Net.Async library.
/// </summary>
[Obsolete("This is superceded by the ParallelForwardingAppender, this will be removed in v8")]
[Obsolete("This is superceded by the ParallelForwardingAppender, this will be removed in v8, do not use this")]
[EditorBrowsable(EditorBrowsableState.Never)]
public class AsynchronousRollingFileAppender : RollingFileAppender
{

297
src/Umbraco.Core/Logging/ParallelForwardingAppender.cs
View File

@@ -13,301 +13,8 @@ namespace Umbraco.Core.Logging
/// <remarks>
/// Borrowed from https://github.com/cjbhaines/Log4Net.Async - will reference Nuget packages directly in v8
/// </remarks>
public class ParallelForwardingAppender : AsyncForwardingAppenderBase, IDisposable
[Obsolete("Use the Log4Net.Async.ParallelForwardingAppender instead this will be removed in future versions")]
public class ParallelForwardingAppender : Log4Net.Async.ParallelForwardingAppender
{
#region Private Members
private const int DefaultBufferSize = 1000;
private BlockingCollection<LoggingEventContext> _loggingEvents;
private CancellationTokenSource _loggingCancelationTokenSource;
private CancellationToken _loggingCancelationToken;
private Task _loggingTask;
private Double _shutdownFlushTimeout = 2;
private TimeSpan _shutdownFlushTimespan = TimeSpan.FromSeconds(2);
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, HttpContext), _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))
{
HttpContext = entry.HttpContext;
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
}
}

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

@@ -59,6 +59,9 @@
<Reference Include="log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a, processorArchitecture=MSIL">
<HintPath>..\packages\log4net.2.0.8\lib\net45-full\log4net.dll</HintPath>
</Reference>
<Reference Include="Log4Net.Async, Version=2.0.4.0, Culture=neutral, processorArchitecture=MSIL">
<HintPath>..\packages\Log4Net.Async.2.0.4\lib\net40\Log4Net.Async.dll</HintPath>
</Reference>
<Reference Include="Microsoft.AspNet.Identity.Core, Version=2.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35, processorArchitecture=MSIL">
<HintPath>..\packages\Microsoft.AspNet.Identity.Core.2.2.1\lib\net45\Microsoft.AspNet.Identity.Core.dll</HintPath>
<Private>True</Private>

1
src/Umbraco.Core/packages.config
View File

@@ -4,6 +4,7 @@
<package id="HtmlAgilityPack" version="1.4.9.5" targetFramework="net45" />
<package id="ImageProcessor" version="2.5.3" targetFramework="net45" />
<package id="log4net" version="2.0.8" targetFramework="net45" />
<package id="Log4Net.Async" version="2.0.4" targetFramework="net45" />
<package id="Microsoft.AspNet.Identity.Core" version="2.2.1" targetFramework="net45" />
<package id="Microsoft.AspNet.Identity.Owin" version="2.2.1" targetFramework="net45" />
<package id="Microsoft.Owin" version="3.0.1" targetFramework="net45" />

168
src/Umbraco.Tests/Logging/AsyncRollingFileAppenderTest.cs
View File

@@ -1,168 +0,0 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
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]
[Ignore]
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;
Debug.Print("{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");
}
}
}

25
src/Umbraco.Tests/Logging/DebugAppender.cs
View File

@@ -1,25 +0,0 @@
using System;
using System.Threading;
using log4net.Appender;
using log4net.Core;
namespace Umbraco.Tests.Logging
{
/// <summary>
/// Borrowed from https://github.com/cjbhaines/Log4Net.Async - will reference Nuget packages directly in v8
/// </summary>
public 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);
}
}
}

327
src/Umbraco.Tests/Logging/ParallelForwarderTest.cs
View File

@@ -1,327 +0,0 @@
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
{
/// <summary>
/// Borrowed from https://github.com/cjbhaines/Log4Net.Async - will reference Nuget packages directly in v8
/// </summary>
[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(30);
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));
Debug.Print("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.");
Debug.Print("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."));
Debug.Print("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);
}
}
}

150
src/Umbraco.Tests/Logging/RingBufferTest.cs
View File

@@ -1,150 +0,0 @@
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
{
/// <summary>
/// Borrowed from https://github.com/cjbhaines/Log4Net.Async - will reference Nuget packages directly in v8
/// </summary>
[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);
}
}
}

2
src/Umbraco.Tests/Scheduling/BackgroundTaskRunnerTests2.cs
View File

@@ -3,7 +3,7 @@ using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;
using NUnit.Framework;
using Umbraco.Tests.Logging;
using Umbraco.Tests.TestHelpers;
using Umbraco.Web.Scheduling;
namespace Umbraco.Tests.Scheduling

2
src/Umbraco.Tests/Logging/ConsoleLogger.cs → src/Umbraco.Tests/TestHelpers/ConsoleLogger.cs
View File

@@ -2,7 +2,7 @@
using System.Linq;
using Umbraco.Core.Logging;
namespace Umbraco.Tests.Logging
namespace Umbraco.Tests.TestHelpers
{
public class ConsoleLogger : ILogger
{

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

@@ -70,6 +70,9 @@
<Reference Include="log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a, processorArchitecture=MSIL">
<HintPath>..\packages\log4net.2.0.8\lib\net45-full\log4net.dll</HintPath>
</Reference>
<Reference Include="Log4Net.Async, Version=2.0.4.0, Culture=neutral, processorArchitecture=MSIL">
<HintPath>..\packages\Log4Net.Async.2.0.4\lib\net40\Log4Net.Async.dll</HintPath>
</Reference>
<Reference Include="Lucene.Net, Version=2.9.4.1, Culture=neutral, PublicKeyToken=85089178b9ac3181, processorArchitecture=MSIL">
<HintPath>..\packages\Lucene.Net.2.9.4.1\lib\net40\Lucene.Net.dll</HintPath>
</Reference>
@@ -165,7 +168,7 @@
<Compile Include="Issues\U9560.cs" />
<Compile Include="Collections\OrderedHashSetTests.cs" />
<Compile Include="IO\ShadowFileSystemTests.cs" />
<Compile Include="Logging\ConsoleLogger.cs" />
<Compile Include="TestHelpers\ConsoleLogger.cs" />
<Compile Include="Migrations\CreateTableMigrationTests.cs" />
<Compile Include="Migrations\MigrationIssuesTests.cs" />
<Compile Include="Persistence\LocksTests.cs" />
@@ -207,9 +210,6 @@
<Compile Include="Collections\DeepCloneableListTests.cs" />
<Compile Include="Web\Controllers\BackOfficeControllerUnitTests.cs" />
<Compile Include="DelegateExtensionsTests.cs" />
<Compile Include="Logging\AsyncRollingFileAppenderTest.cs" />
<Compile Include="Logging\DebugAppender.cs" />
<Compile Include="Logging\ParallelForwarderTest.cs" />
<Compile Include="Web\Mvc\RenderIndexActionSelectorAttributeTests.cs" />
<Compile Include="Persistence\Repositories\AuditRepositoryTest.cs" />
<Compile Include="Persistence\Repositories\DomainRepositoryTest.cs" />
@@ -487,7 +487,6 @@
<Compile Include="PublishedContent\PublishedContentMoreTests.cs" />
<Compile Include="Publishing\PublishingStrategyTests.cs" />
<Compile Include="Resolvers\ActionsResolverTests.cs" />
<Compile Include="Logging\RingBufferTest.cs" />
<Compile Include="TestHelpers\BaseUmbracoConfigurationTest.cs" />
<Compile Include="TestHelpers\DatabaseTestBehaviorAttribute.cs" />
<Compile Include="TestHelpers\Entities\MockedMember.cs" />

1
src/Umbraco.Tests/packages.config
View File

@@ -5,6 +5,7 @@
<package id="Castle.Core" version="4.0.0" targetFramework="net45" />
<package id="Examine" version="0.1.82" targetFramework="net45" />
<package id="log4net" version="2.0.8" targetFramework="net45" />
<package id="Log4Net.Async" version="2.0.4" targetFramework="net45" />
<package id="Lucene.Net" version="2.9.4.1" targetFramework="net45" />
<package id="Microsoft.AspNet.Mvc" version="5.2.3" targetFramework="net45" />
<package id="Microsoft.AspNet.Razor" version="3.2.3" targetFramework="net45" />

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

@@ -18,7 +18,7 @@
<encoding value="utf-8" />
</appender>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.ParallelForwardingAppender,Umbraco.Core">
<appender name="AsynchronousLog4NetAppender" type="Log4Net.Async.ParallelForwardingAppender,Log4Net.Async">
<appender-ref ref="rollingFile" />
</appender>

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

@@ -18,7 +18,7 @@
<encoding value="utf-8" />
</appender>
<appender name="AsynchronousLog4NetAppender" type="Umbraco.Core.Logging.ParallelForwardingAppender,Umbraco.Core">
<appender name="AsynchronousLog4NetAppender" type="Log4Net.Async.ParallelForwardingAppender,Log4Net.Async">
<appender-ref ref="rollingFile" />
</appender>