feat(logging): 扩展ILogAppender接口并实现时间提供者注入

- 将ILogAppender接口继承IDisposable以支持资源释放
- 添加ITimeProvider和SystemTimeProvider接口及实现类
- 创建FakeTimeProvider用于测试时间控制
- 修改SamplingFilter支持时间提供者注入和最大日志记录器数量限制
- 为SamplingFilter添加过期状态清理功能
- 修改StatisticsAppender使用时间提供者并实现IDisposable
- 更新相关单元测试以使用FakeTimeProvider进行精确时间控制
- 在测试类中为模拟追加器添加Dispose方法实现
This commit is contained in:
GeWuYou 2026-03-05 16:03:02 +08:00 committed by gewuyou
parent cd407dc93c
commit ae8c3e4fc4
10 changed files with 265 additions and 31 deletions

View File

@ -3,7 +3,7 @@ namespace GFramework.Core.Abstractions.logging;
/// <summary> /// <summary>
/// 日志输出器接口,负责将日志条目写入特定目标 /// 日志输出器接口,负责将日志条目写入特定目标
/// </summary> /// </summary>
public interface ILogAppender public interface ILogAppender : IDisposable
{ {
/// <summary> /// <summary>
/// 追加日志条目 /// 追加日志条目

View File

@ -0,0 +1,12 @@
namespace GFramework.Core.Abstractions.time;
/// <summary>
/// 时间提供者接口,用于抽象时间获取以支持测试
/// </summary>
public interface ITimeProvider
{
/// <summary>
/// 获取当前 UTC 时间
/// </summary>
DateTime UtcNow { get; }
}

View File

@ -184,6 +184,10 @@ public class AsyncLogAppenderTests
public void Flush() public void Flush()
{ {
} }
public void Dispose()
{
}
} }
private class SlowAppender : ILogAppender private class SlowAppender : ILogAppender
@ -203,6 +207,10 @@ public class AsyncLogAppenderTests
public void Flush() public void Flush()
{ {
} }
public void Dispose()
{
}
} }
private class ThrowingAppender : ILogAppender private class ThrowingAppender : ILogAppender
@ -215,5 +223,9 @@ public class AsyncLogAppenderTests
public void Flush() public void Flush()
{ {
} }
public void Dispose()
{
}
} }
} }

View File

@ -160,6 +160,10 @@ public class CompositeLoggerTests
{ {
FlushCalled = true; FlushCalled = true;
} }
public void Dispose()
{
}
} }
private class TestDisposableAppender : ILogAppender, IDisposable private class TestDisposableAppender : ILogAppender, IDisposable

View File

@ -1,5 +1,6 @@
using GFramework.Core.Abstractions.logging; using GFramework.Core.Abstractions.logging;
using GFramework.Core.logging.filters; using GFramework.Core.logging.filters;
using GFramework.Core.Tests.time;
using NUnit.Framework; using NUnit.Framework;
namespace GFramework.Core.Tests.logging; namespace GFramework.Core.Tests.logging;
@ -10,9 +11,10 @@ public class SamplingFilterTests
[Test] [Test]
public void SamplingFilter_Should_Sample_Logs_By_Rate() public void SamplingFilter_Should_Sample_Logs_By_Rate()
{ {
var filter = new SamplingFilter(sampleRate: 3, timeWindow: TimeSpan.FromMinutes(1)); var timeProvider = new FakeTimeProvider();
var filter = new SamplingFilter(sampleRate: 3, timeWindow: TimeSpan.FromMinutes(1), timeProvider: timeProvider);
var entry = new LogEntry( var entry = new LogEntry(
DateTime.UtcNow, timeProvider.UtcNow,
LogLevel.Info, LogLevel.Info,
"TestLogger", "TestLogger",
"Test message", "Test message",
@ -34,9 +36,11 @@ public class SamplingFilterTests
[Test] [Test]
public void SamplingFilter_Should_Reset_After_Time_Window() public void SamplingFilter_Should_Reset_After_Time_Window()
{ {
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMilliseconds(100)); var timeProvider = new FakeTimeProvider();
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMilliseconds(100),
timeProvider: timeProvider);
var entry = new LogEntry( var entry = new LogEntry(
DateTime.UtcNow, timeProvider.UtcNow,
LogLevel.Info, LogLevel.Info,
"TestLogger", "TestLogger",
"Test message", "Test message",
@ -48,8 +52,8 @@ public class SamplingFilterTests
Assert.That(filter.ShouldLog(entry), Is.True); // 1st Assert.That(filter.ShouldLog(entry), Is.True); // 1st
Assert.That(filter.ShouldLog(entry), Is.False); // 2nd Assert.That(filter.ShouldLog(entry), Is.False); // 2nd
// 等待时间窗口过期 // 前进时间超过窗口
Thread.Sleep(150); timeProvider.Advance(TimeSpan.FromMilliseconds(150));
// 新窗口应该重置计数 // 新窗口应该重置计数
Assert.That(filter.ShouldLog(entry), Is.True); // 1st in new window Assert.That(filter.ShouldLog(entry), Is.True); // 1st in new window
@ -59,10 +63,11 @@ public class SamplingFilterTests
[Test] [Test]
public void SamplingFilter_Should_Maintain_Separate_State_Per_Logger() public void SamplingFilter_Should_Maintain_Separate_State_Per_Logger()
{ {
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1)); var timeProvider = new FakeTimeProvider();
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1), timeProvider: timeProvider);
var entry1 = new LogEntry(DateTime.UtcNow, LogLevel.Info, "Logger1", "Message", null, null); var entry1 = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "Logger1", "Message", null, null);
var entry2 = new LogEntry(DateTime.UtcNow, LogLevel.Info, "Logger2", "Message", null, null); var entry2 = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "Logger2", "Message", null, null);
// Logger1 的第一条 // Logger1 的第一条
Assert.That(filter.ShouldLog(entry1), Is.True); Assert.That(filter.ShouldLog(entry1), Is.True);
@ -77,6 +82,47 @@ public class SamplingFilterTests
Assert.That(filter.ShouldLog(entry2), Is.False); Assert.That(filter.ShouldLog(entry2), Is.False);
} }
[Test]
public void SamplingFilter_Should_Use_Shared_State_When_Max_Loggers_Exceeded()
{
var timeProvider = new FakeTimeProvider();
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1), maxLoggers: 2,
timeProvider: timeProvider);
var entry1 = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "Logger1", "Message", null, null);
var entry2 = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "Logger2", "Message", null, null);
var entry3 = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "Logger3", "Message", null, null);
// Logger1 和 Logger2 各自独立
Assert.That(filter.ShouldLog(entry1), Is.True); // Logger1: 1st
Assert.That(filter.ShouldLog(entry2), Is.True); // Logger2: 1st
// Logger3 超过限制,使用共享状态
Assert.That(filter.ShouldLog(entry3), Is.True); // Shared: 1st
Assert.That(filter.ShouldLog(entry3), Is.False); // Shared: 2nd
}
[Test]
public void SamplingFilter_Should_Cleanup_Stale_States()
{
var timeProvider = new FakeTimeProvider();
var filter = new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1), timeProvider: timeProvider);
var entry = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "TestLogger", "Message", null, null);
// 使用过滤器
filter.ShouldLog(entry);
// 前进时间
timeProvider.Advance(TimeSpan.FromHours(2));
// 清理过期状态
filter.CleanupStaleStates(TimeSpan.FromHours(1));
// 验证状态已被清理(通过再次使用应该重新开始计数)
Assert.That(filter.ShouldLog(entry), Is.True); // 应该是新的第一条
}
[Test] [Test]
public void SamplingFilter_Should_Throw_When_SampleRate_Is_Invalid() public void SamplingFilter_Should_Throw_When_SampleRate_Is_Invalid()
{ {
@ -102,11 +148,27 @@ public class SamplingFilterTests
}); });
} }
[Test]
public void SamplingFilter_Should_Throw_When_MaxLoggers_Is_Invalid()
{
Assert.Throws<ArgumentException>(() =>
{
new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1), maxLoggers: 0);
});
Assert.Throws<ArgumentException>(() =>
{
new SamplingFilter(sampleRate: 2, timeWindow: TimeSpan.FromMinutes(1), maxLoggers: -1);
});
}
[Test] [Test]
public void SamplingFilter_Should_Be_Thread_Safe() public void SamplingFilter_Should_Be_Thread_Safe()
{ {
var filter = new SamplingFilter(sampleRate: 10, timeWindow: TimeSpan.FromMinutes(1)); var timeProvider = new FakeTimeProvider();
var entry = new LogEntry(DateTime.UtcNow, LogLevel.Info, "TestLogger", "Message", null, null); var filter = new SamplingFilter(sampleRate: 10, timeWindow: TimeSpan.FromMinutes(1),
timeProvider: timeProvider);
var entry = new LogEntry(timeProvider.UtcNow, LogLevel.Info, "TestLogger", "Message", null, null);
var passedCount = 0; var passedCount = 0;
var tasks = new List<Task>(); var tasks = new List<Task>();

View File

@ -1,5 +1,6 @@
using GFramework.Core.Abstractions.logging; using GFramework.Core.Abstractions.logging;
using GFramework.Core.logging.appenders; using GFramework.Core.logging.appenders;
using GFramework.Core.Tests.time;
using NUnit.Framework; using NUnit.Framework;
namespace GFramework.Core.Tests.logging; namespace GFramework.Core.Tests.logging;
@ -10,14 +11,17 @@ public class StatisticsAppenderTests
[SetUp] [SetUp]
public void SetUp() public void SetUp()
{ {
_appender = new StatisticsAppender(); _timeProvider = new FakeTimeProvider();
_appender = new StatisticsAppender(_timeProvider);
} }
[TearDown] [TearDown]
public void TearDown() public void TearDown()
{ {
_appender.Dispose();
} }
private FakeTimeProvider _timeProvider = null!;
private StatisticsAppender _appender = null!; private StatisticsAppender _appender = null!;
[Test] [Test]
@ -86,9 +90,9 @@ public class StatisticsAppenderTests
public void StatisticsAppender_Should_Track_Uptime() public void StatisticsAppender_Should_Track_Uptime()
{ {
var startTime = _appender.StartTime; var startTime = _appender.StartTime;
Thread.Sleep(100); _timeProvider.Advance(TimeSpan.FromSeconds(100));
Assert.That(_appender.Uptime, Is.GreaterThanOrEqualTo(TimeSpan.FromMilliseconds(100))); Assert.That(_appender.Uptime, Is.EqualTo(TimeSpan.FromSeconds(100)));
Assert.That(_appender.StartTime, Is.EqualTo(startTime)); Assert.That(_appender.StartTime, Is.EqualTo(startTime));
} }
@ -102,7 +106,7 @@ public class StatisticsAppenderTests
Assert.That(_appender.ErrorCount, Is.EqualTo(1)); Assert.That(_appender.ErrorCount, Is.EqualTo(1));
var oldStartTime = _appender.StartTime; var oldStartTime = _appender.StartTime;
Thread.Sleep(10); _timeProvider.Advance(TimeSpan.FromSeconds(10));
_appender.Reset(); _appender.Reset();
Assert.That(_appender.TotalCount, Is.EqualTo(0)); Assert.That(_appender.TotalCount, Is.EqualTo(0));
@ -172,10 +176,10 @@ public class StatisticsAppenderTests
Assert.DoesNotThrow(() => _appender.Flush()); Assert.DoesNotThrow(() => _appender.Flush());
} }
private static LogEntry CreateLogEntry(LogLevel level, string loggerName, string message) private LogEntry CreateLogEntry(LogLevel level, string loggerName, string message)
{ {
return new LogEntry( return new LogEntry(
DateTime.UtcNow, _timeProvider.UtcNow,
level, level,
loggerName, loggerName,
message, message,

View File

@ -0,0 +1,41 @@
using GFramework.Core.Abstractions.time;
namespace GFramework.Core.Tests.time;
/// <summary>
/// 可控制的时间提供者,用于测试
/// </summary>
public sealed class FakeTimeProvider : ITimeProvider
{
private DateTime _currentTime;
/// <summary>
/// 创建可控制的时间提供者
/// </summary>
/// <param name="initialTime">初始时间,默认为 2024-01-01 00:00:00 UTC</param>
public FakeTimeProvider(DateTime? initialTime = null)
{
_currentTime = initialTime ?? new DateTime(2024, 1, 1, 0, 0, 0, DateTimeKind.Utc);
}
/// <summary>
/// 获取当前时间
/// </summary>
public DateTime UtcNow => _currentTime;
/// <summary>
/// 前进指定的时间
/// </summary>
public void Advance(TimeSpan duration)
{
_currentTime = _currentTime.Add(duration);
}
/// <summary>
/// 设置当前时间
/// </summary>
public void SetTime(DateTime time)
{
_currentTime = time;
}
}

View File

@ -1,6 +1,8 @@
using System.Collections.Concurrent; using System.Collections.Concurrent;
using System.Text; using System.Text;
using GFramework.Core.Abstractions.logging; using GFramework.Core.Abstractions.logging;
using GFramework.Core.Abstractions.time;
using GFramework.Core.time;
namespace GFramework.Core.logging.appenders; namespace GFramework.Core.logging.appenders;
@ -12,10 +14,21 @@ public sealed class StatisticsAppender : ILogAppender
{ {
private readonly ConcurrentDictionary<LogLevel, long> _levelCounts = new(); private readonly ConcurrentDictionary<LogLevel, long> _levelCounts = new();
private readonly ConcurrentDictionary<string, long> _loggerCounts = new(); private readonly ConcurrentDictionary<string, long> _loggerCounts = new();
private readonly ITimeProvider _timeProvider;
private long _errorCount; private long _errorCount;
private DateTime _startTime = DateTime.UtcNow; private long _startTimeTicks;
private long _totalCount; private long _totalCount;
/// <summary>
/// 创建日志统计 Appender
/// </summary>
/// <param name="timeProvider">时间提供者,默认使用系统时间</param>
public StatisticsAppender(ITimeProvider? timeProvider = null)
{
_timeProvider = timeProvider ?? new SystemTimeProvider();
_startTimeTicks = _timeProvider.UtcNow.Ticks;
}
/// <summary> /// <summary>
/// 获取总日志数量 /// 获取总日志数量
/// </summary> /// </summary>
@ -29,12 +42,12 @@ public sealed class StatisticsAppender : ILogAppender
/// <summary> /// <summary>
/// 获取统计开始时间 /// 获取统计开始时间
/// </summary> /// </summary>
public DateTime StartTime => _startTime; public DateTime StartTime => new(Interlocked.Read(ref _startTimeTicks), DateTimeKind.Utc);
/// <summary> /// <summary>
/// 获取运行时长 /// 获取运行时长
/// </summary> /// </summary>
public TimeSpan Uptime => DateTime.UtcNow - _startTime; public TimeSpan Uptime => _timeProvider.UtcNow - StartTime;
/// <summary> /// <summary>
/// 获取错误率(错误数 / 总数) /// 获取错误率(错误数 / 总数)
@ -77,6 +90,14 @@ public sealed class StatisticsAppender : ILogAppender
// 统计 Appender 不需要刷新 // 统计 Appender 不需要刷新
} }
/// <summary>
/// 释放资源
/// </summary>
public void Dispose()
{
// 无需释放资源
}
/// <summary> /// <summary>
/// 获取指定级别的日志数量 /// 获取指定级别的日志数量
/// </summary> /// </summary>
@ -118,7 +139,7 @@ public sealed class StatisticsAppender : ILogAppender
Interlocked.Exchange(ref _errorCount, 0); Interlocked.Exchange(ref _errorCount, 0);
_levelCounts.Clear(); _levelCounts.Clear();
_loggerCounts.Clear(); _loggerCounts.Clear();
_startTime = DateTime.UtcNow; Interlocked.Exchange(ref _startTimeTicks, _timeProvider.UtcNow.Ticks);
} }
/// <summary> /// <summary>
@ -127,8 +148,11 @@ public sealed class StatisticsAppender : ILogAppender
public string GenerateReport() public string GenerateReport()
{ {
var report = new StringBuilder(); var report = new StringBuilder();
var startTime = StartTime;
var now = _timeProvider.UtcNow;
report.AppendLine("=== 日志统计报告 ==="); report.AppendLine("=== 日志统计报告 ===");
report.AppendLine($"统计时间: {_startTime:yyyy-MM-dd HH:mm:ss} - {DateTime.UtcNow:yyyy-MM-dd HH:mm:ss}"); report.AppendLine($"统计时间: {startTime:yyyy-MM-dd HH:mm:ss} - {now:yyyy-MM-dd HH:mm:ss}");
report.AppendLine($"运行时长: {Uptime}"); report.AppendLine($"运行时长: {Uptime}");
report.AppendLine($"总日志数: {TotalCount}"); report.AppendLine($"总日志数: {TotalCount}");
report.AppendLine($"错误日志数: {ErrorCount}"); report.AppendLine($"错误日志数: {ErrorCount}");

View File

@ -1,5 +1,7 @@
using System.Collections.Concurrent; using System.Collections.Concurrent;
using GFramework.Core.Abstractions.logging; using GFramework.Core.Abstractions.logging;
using GFramework.Core.Abstractions.time;
using GFramework.Core.time;
namespace GFramework.Core.logging.filters; namespace GFramework.Core.logging.filters;
@ -9,8 +11,11 @@ namespace GFramework.Core.logging.filters;
/// </summary> /// </summary>
public sealed class SamplingFilter : ILogFilter public sealed class SamplingFilter : ILogFilter
{ {
private const int DefaultMaxLoggers = 1000;
private readonly int _maxLoggers;
private readonly int _sampleRate; private readonly int _sampleRate;
private readonly ConcurrentDictionary<string, SamplingState> _samplingStates = new(); private readonly ConcurrentDictionary<string, SamplingState> _samplingStates = new();
private readonly ITimeProvider _timeProvider;
private readonly TimeSpan _timeWindow; private readonly TimeSpan _timeWindow;
/// <summary> /// <summary>
@ -18,7 +23,13 @@ public sealed class SamplingFilter : ILogFilter
/// </summary> /// </summary>
/// <param name="sampleRate">采样率(每 N 条日志保留 1 条)</param> /// <param name="sampleRate">采样率(每 N 条日志保留 1 条)</param>
/// <param name="timeWindow">时间窗口(在此时间内应用采样)</param> /// <param name="timeWindow">时间窗口(在此时间内应用采样)</param>
public SamplingFilter(int sampleRate, TimeSpan timeWindow) /// <param name="maxLoggers">最大日志记录器数量,超过后使用共享状态</param>
/// <param name="timeProvider">时间提供者,默认使用系统时间</param>
public SamplingFilter(
int sampleRate,
TimeSpan timeWindow,
int maxLoggers = DefaultMaxLoggers,
ITimeProvider? timeProvider = null)
{ {
if (sampleRate <= 0) if (sampleRate <= 0)
throw new ArgumentException("Sample rate must be greater than 0", nameof(sampleRate)); throw new ArgumentException("Sample rate must be greater than 0", nameof(sampleRate));
@ -26,8 +37,13 @@ public sealed class SamplingFilter : ILogFilter
if (timeWindow <= TimeSpan.Zero) if (timeWindow <= TimeSpan.Zero)
throw new ArgumentException("Time window must be greater than zero", nameof(timeWindow)); throw new ArgumentException("Time window must be greater than zero", nameof(timeWindow));
if (maxLoggers <= 0)
throw new ArgumentException("Max loggers must be greater than 0", nameof(maxLoggers));
_sampleRate = sampleRate; _sampleRate = sampleRate;
_timeWindow = timeWindow; _timeWindow = timeWindow;
_maxLoggers = maxLoggers;
_timeProvider = timeProvider ?? new SystemTimeProvider();
} }
/// <summary> /// <summary>
@ -35,32 +51,71 @@ public sealed class SamplingFilter : ILogFilter
/// </summary> /// </summary>
public bool ShouldLog(LogEntry entry) public bool ShouldLog(LogEntry entry)
{ {
// 为每个日志记录器维护独立的采样状态 // 如果超过最大日志记录器数量,使用共享状态
var key = entry.LoggerName; var key = _samplingStates.Count >= _maxLoggers ? "*" : entry.LoggerName;
var state = _samplingStates.GetOrAdd(key, _ => new SamplingState());
var state = _samplingStates.GetOrAdd(key, _ => new SamplingState(_timeProvider));
return state.ShouldLog(_sampleRate, _timeWindow); return state.ShouldLog(_sampleRate, _timeWindow);
} }
/// <summary>
/// 清理过期的采样状态
/// </summary>
public void CleanupStaleStates(TimeSpan staleThreshold)
{
var now = _timeProvider.UtcNow;
var keysToRemove = new List<string>();
foreach (var kvp in _samplingStates)
{
if (kvp.Key == "*") continue; // 不清理共享状态
if (kvp.Value.IsStale(now, staleThreshold))
{
keysToRemove.Add(kvp.Key);
}
}
foreach (var key in keysToRemove)
{
_samplingStates.TryRemove(key, out _);
}
}
/// <summary> /// <summary>
/// 采样状态 /// 采样状态
/// </summary> /// </summary>
private sealed class SamplingState private sealed class SamplingState
{ {
private readonly object _lock = new(); private readonly object _lock = new();
private readonly ITimeProvider _timeProvider;
private long _count; private long _count;
private DateTime _windowStart = DateTime.UtcNow; private long _lastAccessTicks;
private long _windowStartTicks;
public SamplingState(ITimeProvider timeProvider)
{
_timeProvider = timeProvider;
var now = timeProvider.UtcNow.Ticks;
_windowStartTicks = now;
_lastAccessTicks = now;
}
public bool ShouldLog(int sampleRate, TimeSpan timeWindow) public bool ShouldLog(int sampleRate, TimeSpan timeWindow)
{ {
lock (_lock) lock (_lock)
{ {
var now = DateTime.UtcNow; var now = _timeProvider.UtcNow;
var nowTicks = now.Ticks;
Interlocked.Exchange(ref _lastAccessTicks, nowTicks);
var windowStart = new DateTime(Interlocked.Read(ref _windowStartTicks), DateTimeKind.Utc);
// 检查是否需要重置时间窗口 // 检查是否需要重置时间窗口
if (now - _windowStart >= timeWindow) if (now - windowStart >= timeWindow)
{ {
_windowStart = now; Interlocked.Exchange(ref _windowStartTicks, nowTicks);
_count = 0; _count = 0;
} }
@ -70,5 +125,11 @@ public sealed class SamplingFilter : ILogFilter
return _count % sampleRate == 1; return _count % sampleRate == 1;
} }
} }
public bool IsStale(DateTime now, TimeSpan staleThreshold)
{
var lastAccess = new DateTime(Interlocked.Read(ref _lastAccessTicks), DateTimeKind.Utc);
return now - lastAccess > staleThreshold;
}
} }
} }

View File

@ -0,0 +1,14 @@
using GFramework.Core.Abstractions.time;
namespace GFramework.Core.time;
/// <summary>
/// 系统时间提供者,返回真实的系统时间
/// </summary>
public sealed class SystemTimeProvider : ITimeProvider
{
/// <summary>
/// 获取当前 UTC 时间
/// </summary>
public DateTime UtcNow => DateTime.UtcNow;
}