[ https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Stefan Bodewig resolved LOG4NET-376. ------------------------------------ Resolution: Fixed svn revision 1670334 uses ThreadStatic for log4net 1.3.0 - in my (limited) tests the TreadStatic version has been a lot faster than the one using locks on Mono 3.2 and both versions showed about the same performance on .NET 4.0. > Race condition in AbsoluteTimeDateFormatter > ------------------------------------------- > > Key: LOG4NET-376 > URL: https://issues.apache.org/jira/browse/LOG4NET-376 > Project: Log4net > Issue Type: Bug > Affects Versions: 1.2.11 > Reporter: Stuart Lange > Fix For: 1.3.0, 1.2.13 > > > AbsoluteTimeDateFormatter's caching of the "to the second" timestamp string > is not thread-safe. It is possible for one thread to clear the check (that > this timestamp matches the currently cached "to the second" timestamp), but > then end up using an incorrect "to the second" timestamp string if another > thread has changed it in the meantime. > In our organization, we see this bug fairly regularly because we have a mix > of "real time" loggers that immediately write out log lines and "batching" > loggers that defer logging to a background task that runs every second. We > therefore regularly see log lines where the timestamp is off by a second or > two. > The following unit tests demonstrates the bug: > [TestFixture] > [Explicit] > public class Log4netTimestampBug > { > /// <summary> > /// This test demonstrates a bug with the log4net default time > formatter (Iso8601DateFormatter) > /// where the logged timestamp can be seconds off from the actual > input timestamp > /// The bug is caused to a race condition in the base class > AbsoluteTimeDateFormatter > /// because this class caches the timestamp string to the second but > it is possible for > /// the timestamp as written by a different thread to "sneak in" and > be used by another > /// thread erroneously (the checking and usage of this string is not > done under a lock, only > /// its modification) > /// </summary> > [Test] > public void Test() > { > var now = DateTime.Now; > var times = Enumerable.Range(1, 1000000).Select(i => > now.AddMilliseconds(i)).ToList(); > var sb1 = new StringBuilder(); > var sb2 = new StringBuilder(); > var task1 = Task.Run(() => WriteAllTheTimes(times, new > StringWriter(sb1))); > var task2 = Task.Delay(50).ContinueWith(t => > WriteAllTheTimes(times, new StringWriter(sb2))); > Task.WaitAll(task1, task2); > var task1Strings = GetTimeStrings(sb1); > var task2Strings = GetTimeStrings(sb2); > var diffs = Enumerable.Range(0, times.Count).Where(i => > task1Strings[i] != task2Strings[i]).ToList(); > Console.WriteLine("found {0} instances where the formatted > timestamps are not the same", diffs.Count); > Console.WriteLine(); > var diffToLookAt = diffs.FirstOrDefault(i => i - 10 > 0 && i + 10 > < times.Count); > if (diffToLookAt != 0) > { > Console.WriteLine("Example Diff:"); > Console.WriteLine(); > Console.WriteLine("Index Original Timestamp Task 1 > Format Task 2 Format"); > for (int i = diffToLookAt - 10; i < diffToLookAt + 10; i++) > { > Console.WriteLine("{0,-7} {1} {2} {3} {4}", i, > times[i].ToString("yyyy-MM-dd HH:mm:ss,fff"), > task1Strings[i], task2Strings[i], i == > diffToLookAt ? "**** DIFF HERE ****" : ""); > } > } > CollectionAssert.AreEqual(task1Strings, task2Strings); > } > private static List<string> GetTimeStrings(StringBuilder sb1) > { > return sb1.ToString().Split(new[] {'\r', '\n'}, > StringSplitOptions.RemoveEmptyEntries).ToList(); > } > private static void WriteAllTheTimes(IEnumerable<DateTime> times, > TextWriter writer) > { > var formatter = new Iso8601DateFormatter(); > foreach (var t in times) > { > formatter.FormatDate(t, writer); > writer.WriteLine(); > } > } > } -- This message was sent by Atlassian JIRA (v6.3.4#6332)