Skip to content

Rename test project and update namespaces for consistency #2

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ncipollina merged 3 commits into from
Jun 9, 2025
Merged

Rename test project and update namespaces for consistency #2

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
05d49bb
Rename test project and update namespaces for consistency
ncipollina Jun 9, 2025
e747fa9
Fix structured logging in performance extensions
ncipollina Jun 9, 2025
2e96ad4
Remove generic TimedOperation class and simplify performance extensions
ncipollina Jun 9, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion LayeredCraft.StructuredLogging.sln
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{1BF6691E-696
EndProject
Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "test", "test", "{6FFCCE67-D59F-4089-B3EE-822E5CDD0253}"
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "LayeredCraft.StructuredLogging.Test", "test\LayeredCraft.StructuredLogging.Test\LayeredCraft.StructuredLogging.Test.csproj", "{378ED5C6-96C6-418F-860E-CF48A53E20FD}"
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "LayeredCraft.StructuredLogging.Tests", "test\LayeredCraft.StructuredLogging.Tests\LayeredCraft.StructuredLogging.Tests.csproj", "{378ED5C6-96C6-418F-860E-CF48A53E20FD}"
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "LayeredCraft.StructuredLogging", "src\LayeredCraft.StructuredLogging\LayeredCraft.StructuredLogging.csproj", "{236B0640-4113-4D3F-AF03-D3EBAE3ABA96}"
EndProject
Expand Down
101 changes: 14 additions & 87 deletions src/LayeredCraft.StructuredLogging/PerformanceExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,31 +33,6 @@ public static IDisposable TimeOperation(this ILogger logger, string operationNam
return new TimedOperation(logger, operationName, logLevel);
}

/// <summary>
/// Creates a disposable timer that logs the start and completion time of an operation with additional typed context property.
/// When disposed, it automatically logs the total elapsed time along with the context property.
/// </summary>
/// <typeparam name="T">The type of the context property value.</typeparam>
/// <param name="logger">The logger instance.</param>
/// <param name="operationName">The name of the operation being timed.</param>
/// <param name="propertyName">The name of the context property to include.</param>
/// <param name="propertyValue">The value of the context property to include.</param>
/// <param name="logLevel">The log level to use for timing messages. Defaults to Information.</param>
/// <returns>An IDisposable TimedOperation that logs completion time with context when disposed.</returns>
/// <example>
/// <code>
/// using (logger.TimeOperation("ProcessOrder", "OrderId", orderId))
/// {
/// // Order processing code here
/// // Logs with both timing and OrderId context
/// }
/// </code>
/// </example>
public static IDisposable TimeOperation<T>(this ILogger logger, string operationName, string propertyName, T propertyValue, LogLevel logLevel = LogLevel.Information)
{
return new TimedOperation<T>(logger, operationName, propertyName, propertyValue, logLevel);
}

/// <summary>
/// Executes an asynchronous operation with automatic timing and logging. Logs start, completion, and elapsed time.
/// If the operation throws an exception, logs the failure with timing information and re-throws the exception.
Expand All @@ -79,19 +54,19 @@ public static IDisposable TimeOperation<T>(this ILogger logger, string operation
public static async Task<TResult> TimeAsync<TResult>(this ILogger logger, string operationName, Func<Task<TResult>> operation, LogLevel logLevel = LogLevel.Information)
{
var stopwatch = Stopwatch.StartNew();
logger.LogMessage(logLevel, null, $"Starting operation: {operationName}");
logger.LogMessage(logLevel, null, "Starting operation: {OperationName}", operationName);

try
{
var result = await operation();
stopwatch.Stop();
logger.LogMessage(logLevel, null, $"Completed operation: {operationName} in {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(logLevel, null, "Completed operation: {OperationName} in {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
return result;
}
catch (Exception ex)
{
stopwatch.Stop();
logger.LogMessage(LogLevel.Error, ex, $"Failed operation: {operationName} after {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(LogLevel.Error, ex, "Failed operation: {OperationName} after {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
throw;
}
}
Expand All @@ -116,18 +91,18 @@ public static async Task<TResult> TimeAsync<TResult>(this ILogger logger, string
public static async Task TimeAsync(this ILogger logger, string operationName, Func<Task> operation, LogLevel logLevel = LogLevel.Information)
{
var stopwatch = Stopwatch.StartNew();
logger.LogMessage(logLevel, null, $"Starting operation: {operationName}");
logger.LogMessage(logLevel, null, "Starting operation: {OperationName}", operationName);

try
{
await operation();
stopwatch.Stop();
logger.LogMessage(logLevel, null, $"Completed operation: {operationName} in {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(logLevel, null, "Completed operation: {OperationName} in {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
}
catch (Exception ex)
{
stopwatch.Stop();
logger.LogMessage(LogLevel.Error, ex, $"Failed operation: {operationName} after {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(LogLevel.Error, ex, "Failed operation: {OperationName} after {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
throw;
}
}
Expand All @@ -153,19 +128,19 @@ public static async Task TimeAsync(this ILogger logger, string operationName, Fu
public static TResult Time<TResult>(this ILogger logger, string operationName, Func<TResult> operation, LogLevel logLevel = LogLevel.Information)
{
var stopwatch = Stopwatch.StartNew();
logger.LogMessage(logLevel, null, $"Starting operation: {operationName}");
logger.LogMessage(logLevel, null, "Starting operation: {OperationName}", operationName);

try
{
var result = operation();
stopwatch.Stop();
logger.LogMessage(logLevel, null, $"Completed operation: {operationName} in {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(logLevel, null, "Completed operation: {OperationName} in {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
return result;
}
catch (Exception ex)
{
stopwatch.Stop();
logger.LogMessage(LogLevel.Error, ex, $"Failed operation: {operationName} after {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(LogLevel.Error, ex, "Failed operation: {OperationName} after {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
throw;
}
}
Expand All @@ -189,18 +164,18 @@ public static TResult Time<TResult>(this ILogger logger, string operationName, F
public static void Time(this ILogger logger, string operationName, Action operation, LogLevel logLevel = LogLevel.Information)
{
var stopwatch = Stopwatch.StartNew();
logger.LogMessage(logLevel, null, $"Starting operation: {operationName}");
logger.LogMessage(logLevel, null, "Starting operation: {OperationName}", operationName);

try
{
operation();
stopwatch.Stop();
logger.LogMessage(logLevel, null, $"Completed operation: {operationName} in {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(logLevel, null, "Completed operation: {OperationName} in {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
}
catch (Exception ex)
{
stopwatch.Stop();
logger.LogMessage(LogLevel.Error, ex, $"Failed operation: {operationName} after {stopwatch.ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds);
logger.LogMessage(LogLevel.Error, ex, "Failed operation: {OperationName} after {ElapsedMilliseconds}ms", operationName, stopwatch.ElapsedMilliseconds);
throw;
}
}
Expand Down Expand Up @@ -260,7 +235,7 @@ public TimedOperation(ILogger logger, string operationName, LogLevel logLevel)
_logLevel = logLevel;
_stopwatch = Stopwatch.StartNew();

_logger.LogMessage(_logLevel, null, $"Starting operation: {_operationName}");
_logger.LogMessage(_logLevel, null, "Starting operation: {OperationName}", _operationName);
}

/// <summary>
Expand All @@ -271,55 +246,7 @@ public void Dispose()
if (_disposed) return;

_stopwatch.Stop();
_logger.LogMessage(_logLevel, null, $"Completed operation: {_operationName} in {_stopwatch.ElapsedMilliseconds}ms", _stopwatch.ElapsedMilliseconds);
_logger.LogMessage(_logLevel, null, "Completed operation: {OperationName} in {ElapsedMilliseconds}ms", _operationName, _stopwatch.ElapsedMilliseconds);
_disposed = true;
}
}

/// <summary>
/// Internal generic class that implements a disposable timer for tracking operation duration with additional context.
/// Automatically logs the start time with context when created and the elapsed time with context when disposed.
/// </summary>
/// <typeparam name="T">The type of the context property value.</typeparam>
internal sealed class TimedOperation<T> : IDisposable
{
private readonly ILogger _logger;
private readonly string _operationName;
private readonly string _propertyName;
private readonly T _propertyValue;
private readonly LogLevel _logLevel;
private readonly Stopwatch _stopwatch;
private bool _disposed;

/// <summary>
/// Initializes a new instance of the TimedOperation class with context and starts timing.
/// </summary>
/// <param name="logger">The logger instance to use for logging.</param>
/// <param name="operationName">The name of the operation being timed.</param>
/// <param name="propertyName">The name of the context property.</param>
/// <param name="propertyValue">The value of the context property.</param>
/// <param name="logLevel">The log level to use for timing messages.</param>
public TimedOperation(ILogger logger, string operationName, string propertyName, T propertyValue, LogLevel logLevel)
{
_logger = logger;
_operationName = operationName;
_propertyName = propertyName;
_propertyValue = propertyValue;
_logLevel = logLevel;
_stopwatch = Stopwatch.StartNew();

_logger.LogMessage(_logLevel, null, $"Starting operation: {_operationName}", _propertyValue);
}

/// <summary>
/// Stops timing and logs the total elapsed time with context. Can be called multiple times safely.
/// </summary>
public void Dispose()
{
if (_disposed) return;

_stopwatch.Stop();
_logger.LogMessage<T, long>(_logLevel, null, $"Completed operation: {_operationName} in {_stopwatch.ElapsedMilliseconds}ms", _propertyValue, _stopwatch.ElapsedMilliseconds);
_disposed = true;
}
}
4 changes: 2 additions & 2 deletions ...edLogging.Test/CriticalExtensionsTests.cs → ...dLogging.Tests/CriticalExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class CriticalExtensionsTests
{
Expand Down
4 changes: 2 additions & 2 deletions ...turedLogging.Test/DebugExtensionsTests.cs → ...uredLogging.Tests/DebugExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class DebugExtensionsTests
{
Expand Down
4 changes: 2 additions & 2 deletions ...Logging.Test/EnrichmentExtensionsTests.cs → ...ogging.Tests/EnrichmentExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class EnrichmentExtensionsTests
{
Expand Down
4 changes: 2 additions & 2 deletions ...turedLogging.Test/ErrorExtensionsTests.cs → ...uredLogging.Tests/ErrorExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class ErrorExtensionsTests
{
Expand Down
0 ...ft.StructuredLogging.Test/GlobalUsings.cs → ...t.StructuredLogging.Tests/GlobalUsings.cs
View file
Open in desktop
File renamed without changes.
4 changes: 2 additions & 2 deletions ...ogging.Test/InformationExtensionsTests.cs → ...gging.Tests/InformationExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class InformationExtensionsTests
{
Expand Down
17 changes: 10 additions & 7 deletions ...ayeredCraft.StructuredLogging.Test.csproj → ...yeredCraft.StructuredLogging.Tests.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,11 +4,18 @@
<ImplicitUsings>enable</ImplicitUsings>
<Nullable>enable</Nullable>
<OutputType>Exe</OutputType>
<RootNamespace>LayeredCraft.StructuredLogging.Test</RootNamespace>
<TargetFrameworks>net8.0;net9.0</TargetFrameworks>
<LangVersion>default</LangVersion>
<TestingPlatformDotnetTestSupport>true</TestingPlatformDotnetTestSupport>
<UseMicrosoftTestingPlatformRunner>true</UseMicrosoftTestingPlatformRunner>
<!--
To enable the Microsoft Testing Platform 'dotnet test' experience, add property:
<TestingPlatformDotnetTestSupport>true</TestingPlatformDotnetTestSupport>

To enable the Microsoft Testing Platform native command line experience, add property:
<UseMicrosoftTestingPlatformRunner>true</UseMicrosoftTestingPlatformRunner>

For more information on Microsoft Testing Platform support in xUnit.net, please visit:
https://xunit.net/docs/getting-started/v3/microsoft-testing-platform
-->
</PropertyGroup>

<ItemGroup>
Expand All @@ -33,8 +40,4 @@
<ProjectReference Include="..\..\src\LayeredCraft.StructuredLogging\LayeredCraft.StructuredLogging.csproj" />
</ItemGroup>

<ItemGroup>
<Folder Include=".github\" />
</ItemGroup>

</Project>
92 changes: 2 additions & 90 deletions ...ogging.Test/PerformanceExtensionsTests.cs → ...gging.Tests/PerformanceExtensionsTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
using AutoFixture.Xunit3;
using LayeredCraft.StructuredLogging.Test.TestKit.Attributes;
using LayeredCraft.StructuredLogging.Testing;
using LayeredCraft.StructuredLogging.Tests.TestKit.Attributes;
using Microsoft.Extensions.Logging;

namespace LayeredCraft.StructuredLogging.Test;
namespace LayeredCraft.StructuredLogging.Tests;

public class PerformanceExtensionsTests
{
Expand Down Expand Up @@ -104,94 +104,6 @@ public void TimeOperation_WithLoggerDisabled_DoesNotLog(string operationName)

#endregion

#region TimeOperation<T> Tests

[Theory]
[AutoNSubstituteData]
public void TimeOperation_WithProperty_CreatesDisposableTimer(
string operationName,
string propertyName,
string propertyValue)
{
// Arrange
var testLogger = new TestLogger();

// Act
using var timer = testLogger.TimeOperation(operationName, propertyName, propertyValue);

// Assert
timer.Should().NotBeNull();
testLogger.AssertLogCount(LogLevel.Information, 1);
}

[Theory]
[AutoNSubstituteData]
public void TimeOperation_WithProperty_WhenDisposed_LogsCompletionWithContext(
string operationName,
string propertyName,
string propertyValue)
{
// Arrange
var testLogger = new TestLogger();

// Act
using (var timer = testLogger.TimeOperation(operationName, propertyName, propertyValue))
{
// Timer is active
}

// Assert
testLogger.AssertLogCount(LogLevel.Information, 2);
var entries = testLogger.GetLogEntries(LogLevel.Information).ToList();
entries[0].FormattedMessage.Should().Contain("Starting operation");
entries[0].FormattedMessage.Should().Contain(operationName);
entries[1].FormattedMessage.Should().Contain("Completed operation");
entries[1].FormattedMessage.Should().Contain(operationName);
entries[1].FormattedMessage.Should().Contain("ms");
}

[Theory]
[AutoNSubstituteData]
public void TimeOperation_WithPropertyAndCustomLogLevel_UsesSpecifiedLevel(
string operationName,
string propertyName,
int propertyValue)
{
// Arrange
var testLogger = new TestLogger();

// Act
using (var timer = testLogger.TimeOperation(operationName, propertyName, propertyValue, LogLevel.Debug))
{
// Timer is active
}

// Assert
testLogger.AssertLogCount(LogLevel.Debug, 2);
testLogger.AssertLogCount(LogLevel.Information, 0);
}

[Theory]
[AutoNSubstituteData]
public void TimeOperation_WithNullProperty_CreatesTimer(
string operationName,
string propertyName)
{
// Arrange
var testLogger = new TestLogger();

// Act
using (var timer = testLogger.TimeOperation<string?>(operationName, propertyName, null))
{
// Timer is active
}

// Assert
testLogger.AssertLogCount(LogLevel.Information, 2);
}

#endregion

#region TimeAsync<TResult> Tests

[Theory]
Expand Down
Loading
Loading