[
https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13659516#comment-13659516
]
Stuart Lange commented on LOG4NET-376:
--------------------------------------
The bug is in AbsoluteTimeDateFormatter, so it affects its inheritors --
Iso8601TimeDateFormat and DateTimeFormatter -- as well. SimpleDateFormatter is
not affected. The race condition occurs in
AbsoluteTimeDateFormatter.FormatDate -- the input time, rounded to the nearest
second, is compared to the "last time to the second". If they match, the "last
time string" is written to the stream. However, these two operations are not
done under a lock, so in-between the check and the write, another thread can
change the "last time string".
In typical operations, this isn't a problem. Our issue is that we have some
loggers that batch logging events and defer writing to a background thread, and
some that write logs in "real time". This means that simultaneously, we have
logging events that are "fresh" being written and logging events that are one
or two seconds old being written. This set-up causes us to regularly see
"wrong" timestamps in our log files due to this race condition. I've tried to
roughly replicate this scenario in the unit test.
Thanks for your help.
> 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
>
> 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
