From 7f345f4551cff5d1d8449802e8b9c04d0a3cbbb1 Mon Sep 17 00:00:00 2001 From: Colin Mackay Date: Sun, 23 Feb 2025 21:51:13 +0000 Subject: [PATCH] Fix the timestamps in LogEntry --- release-notes/wip-release-notes.md | 4 +-- .../TestsUsingTheLoggerDirectly.cs | 31 ++++++++----------- .../LogEntry.cs | 8 ++++- 3 files changed, 21 insertions(+), 22 deletions(-) diff --git a/release-notes/wip-release-notes.md b/release-notes/wip-release-notes.md index f15a084..84a636c 100644 --- a/release-notes/wip-release-notes.md +++ b/release-notes/wip-release-notes.md @@ -6,9 +6,7 @@ Date: ??? ### Bug Fixes -### Features - -### Miscellaneous +- #190: Fix issue with timestamps being out of order. ### Dependencies diff --git a/src/Stravaig.Extensions.Logging.Diagnostics.Tests/TestsUsingTheLoggerDirectly.cs b/src/Stravaig.Extensions.Logging.Diagnostics.Tests/TestsUsingTheLoggerDirectly.cs index 87f3536..793183a 100644 --- a/src/Stravaig.Extensions.Logging.Diagnostics.Tests/TestsUsingTheLoggerDirectly.cs +++ b/src/Stravaig.Extensions.Logging.Diagnostics.Tests/TestsUsingTheLoggerDirectly.cs @@ -102,11 +102,13 @@ public void SequenceNumberIncreasedOnEachLogMessageAcrossMultipleLoggers() [Test] public void ManyThreadsAccessingLogger() { + // This test is designed to test that the logger is thread-safe. + // It may take a while to run. const int timeoutMs = 30000; - const int iterationsPerThread = 25000; + const int iterationsPerThread = 250_000; int numThreads = Environment.ProcessorCount * 4; int expectedLogCount = iterationsPerThread * numThreads; - Console.WriteLine($"Performing {iterationsPerThread} iterations on each of {numThreads} threads for an expected total of {expectedLogCount} log messages."); + Console.WriteLine($"[{DateTime.UtcNow:O}] Performing {iterationsPerThread} iterations on each of {numThreads} threads for an expected total of {expectedLogCount} log messages."); Task[] tasks = new Task[numThreads]; var logger = new TestCaptureLogger(); @@ -115,7 +117,7 @@ public void ManyThreadsAccessingLogger() int localTaskNumber = taskNumber; tasks[taskNumber] = Task.Factory.StartNew(() => { - Console.WriteLine($"Starting task {localTaskNumber} on thread {Environment.CurrentManagedThreadId}"); + Console.WriteLine($"[{DateTime.UtcNow:O}] Starting task {localTaskNumber} on thread {Environment.CurrentManagedThreadId}"); for (int i = 0; i < iterationsPerThread; i++) { logger.LogInformation( @@ -123,7 +125,7 @@ public void ManyThreadsAccessingLogger() i, Environment.CurrentManagedThreadId); } - Console.WriteLine($"Finished task {localTaskNumber} on thread {Environment.CurrentManagedThreadId}"); + Console.WriteLine($"[{DateTime.UtcNow:O}] Finished task {localTaskNumber} on thread {Environment.CurrentManagedThreadId}"); }); } @@ -132,31 +134,24 @@ public void ManyThreadsAccessingLogger() tasks.ShouldAllBe(t => t.IsCompleted); var logs = logger.GetLogs(); + Console.WriteLine($"[{DateTime.UtcNow:O}] Should Be {expectedLogCount} logs."); logs.Count.ShouldBe(expectedLogCount); // Check no duplicate sequence numbers + Console.WriteLine($"[{DateTime.UtcNow:O}] Should not have duplicate sequence numbers."); logs.Select(l => l.Sequence).Distinct().Count().ShouldBe(expectedLogCount); // Checks that log entries are in sequence order - logs.ShouldBeInOrder(SortDirection.Ascending); + Console.WriteLine($"[{DateTime.UtcNow:O}] Should be in sequence order."); + logs.Select(l => l.Sequence).ShouldBeInOrder(SortDirection.Ascending); - // Check that timestamps progressed forward-only - Enumerable.Range(0, logs.Count - 2) - .Select( i => new - { - Index = i, - Current = logs[i], - CurrentSequence = logs[i].Sequence, - CurrentTimestamp = logs[i].TimestampUtc.ToString("O"), - Next = logs[i+1], - NextSequence = logs[i+1].Sequence, - NextTimestamp = logs[i+1].TimestampUtc.ToString("O"), - }).ShouldAllBe(e => e.Current.TimestampUtc <= e.Next.TimestampUtc); + Console.WriteLine($"[{DateTime.UtcNow:O}] Should be in timestamp order."); + logs.Select(l => l.TimestampUtc).ShouldBeInOrder(SortDirection.Ascending); DateTime first = logs.First().TimestampUtc; DateTime last = logs.Last().TimestampUtc; first.ShouldBeLessThanOrEqualTo(last); - Console.WriteLine($"Logging started at {first:HH:mm:ss.fff} and ended at {last:HH:mm:ss.fff} taking a total of {(last-first):G}"); + Console.WriteLine($"[{DateTime.UtcNow:O}] Logging started at {first:HH:mm:ss.fff} and ended at {last:HH:mm:ss.fff} taking a total of {(last-first):G}"); } } } diff --git a/src/Stravaig.Extensions.Logging.Diagnostics/LogEntry.cs b/src/Stravaig.Extensions.Logging.Diagnostics/LogEntry.cs index 09f9c2e..291a08b 100644 --- a/src/Stravaig.Extensions.Logging.Diagnostics/LogEntry.cs +++ b/src/Stravaig.Extensions.Logging.Diagnostics/LogEntry.cs @@ -17,6 +17,7 @@ namespace Stravaig.Extensions.Logging.Diagnostics; [DebuggerDisplay("{" + nameof(DebuggerDisplayString) + "}")] public class LogEntry : IComparable { + private static long _lastTimestampUtc; private static int _sequence; #if NET9_0_OR_GREATER private static readonly Lock SequenceSyncLock = new(); @@ -125,7 +126,12 @@ public LogEntry(LogLevel logLevel, EventId eventId, object? state, Exception? ex lock (SequenceSyncLock) { Sequence = _sequence++; - TimestampUtc = DateTime.UtcNow; + + // Ensure monotonicity of the timestamp between log entries, even + // in high-frequency logging scenarios. + var now = DateTime.UtcNow.Ticks; + _lastTimestampUtc = Math.Max(_lastTimestampUtc + 1, now); + TimestampUtc = new DateTime(_lastTimestampUtc, DateTimeKind.Utc); } }