RE: [jira] [Created] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter

[Johnson, Thomas]

lol

-----Original Message-----
From: Johnson, Thomas [mailto:thomas.john...@lpsvcs.com] 
Sent: Monday, May 13, 2013 1:49 PM
To: Log4NET Dev
Subject: RE: [jira] [Created] (LOG4NET-376) Race condition in 
AbsoluteTimeDateFormatter

unsubscribe

-----Original Message-----
From: Stuart Lange (JIRA) [mailto:j...@apache.org] 
Sent: Monday, May 13, 2013 10:19 AM
To: log4net-dev@logging.apache.org
Subject: [jira] [Created] (LOG4NET-376) Race condition in 
AbsoluteTimeDateFormatter

Stuart Lange created LOG4NET-376:
------------------------------------

             Summary: 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

The information contained in this message is proprietary and/or confidential. 
If you are not the intended recipient, please: (i) delete the message and all 
copies; (ii) do not disclose, distribute or use the message in any manner; and 
(iii) notify the sender immediately. In addition, please be aware that any 
message addressed to our domain is subject to archiving and review by persons 
other than the intended recipient. Thank you.
The information contained in this message is proprietary and/or confidential. 
If you are not the intended recipient, please: (i) delete the message and all 
copies; (ii) do not disclose, distribute or use the message in any manner; and 
(iii) notify the sender immediately. In addition, please be aware that any 
message addressed to our domain is subject to archiving and review by persons 
other than the intended recipient. Thank you.