[
https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dominik Psenner reassigned LOG4NET-376:
---------------------------------------
Assignee: Dominik Psenner
> 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
> Assignee: Dominik Psenner
>
> 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 is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
