[jira] [Commented] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter

["Stuart Lange (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13821734#comment-13821734 ] 

Stuart Lange commented on LOG4NET-376:
--------------------------------------

Hello again.  Sorry for letting this slide for a while.

We've noticed that with the log4net 1.2.12 service release, this bug has actually gotten considerably worse.  We have run into scenarios where the "to the second" component of the timestamp gets "stuck" and never updates again for the duration of the application.  Unfortunately, I have been unable to produce a unit test that reliably reproduces the issue (the unit test above sometimes reproduces it), but my best guess is that this is related to the addition of the Hashtable in AbsoluteTimeDateFormatter in LOG4NET-323.  The Hashtable is cleared and read from outside the lock, which can lead to potential race conditions since the Hashtable is not thread-safe.

I have created my own implementation of IDateFormatter that behaves identically to Iso8601DateFormatter, but avoids the bugs noted in this issue.  My performance testing shows that it performs nearly identically to Iso8601DateFormatter in typical scenarios, and actually performs substantially better in multi-threaded scenarios.  I chose to make the cache state ThreadStatic as that performs marginally better than the other options (static, instance) in my performance testing, but the other options also perform well and behave equivalently.  Code is below.  If you would like to see my performance testing code, I can send you that as well, but it uses some of my own custom components that would require unpacking to post in copy-paste friendly form.

    public class StandardDateFormatter : IDateFormatter
    {
        // Using ThreadStatic is a micro-optimization. Making it static or instance state also works.
        // ThreadStatic performs marginally better in scenarios where the same instance of the formatter 
        // is being hit from multiple threads that are using different timestamps.  
        // Performance is roughly equivalent in single-threaded scenarios.
        [ThreadStatic]
        private static Tuple<long, string> _lastTicksToTheSecond;

        public void FormatDate(DateTime dateToFormat, TextWriter writer)
        {
            var ticksToTheSecond = dateToFormat.Ticks - dateToFormat.Ticks % TimeSpan.TicksPerSecond;
            var lastToTheSecond = _lastTicksToTheSecond;
            string toTheSecondString;
            if (lastToTheSecond != null && lastToTheSecond.Item1 == ticksToTheSecond)
            {
                toTheSecondString = lastToTheSecond.Item2;
            }
            else
            {
                toTheSecondString = dateToFormat.ToString("yyyy-MM-dd HH:mm:ss");
                _lastTicksToTheSecond = Tuple.Create(ticksToTheSecond, toTheSecondString);
            }
            writer.Write(toTheSecondString);
            writer.Write(',');
            var millisecond = dateToFormat.Millisecond;
            if (millisecond < 100)
                writer.Write('0');
            if (millisecond < 10)
                writer.Write('0');
            writer.Write(millisecond);
        }
    }


> 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
>             Fix For: 1.2.12
>
>
> 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.1#6144)