Return-Path: X-Original-To: apmail-logging-log4net-dev-archive@www.apache.org Delivered-To: apmail-logging-log4net-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id C040110AE9 for ; Sun, 17 Nov 2013 09:37:21 +0000 (UTC) Received: (qmail 50278 invoked by uid 500); 17 Nov 2013 09:37:21 -0000 Delivered-To: apmail-logging-log4net-dev-archive@logging.apache.org Received: (qmail 50244 invoked by uid 500); 17 Nov 2013 09:37:21 -0000 Mailing-List: contact log4net-dev-help@logging.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Log4NET Dev" List-Id: Delivered-To: mailing list log4net-dev@logging.apache.org Received: (qmail 50234 invoked by uid 99); 17 Nov 2013 09:37:20 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 17 Nov 2013 09:37:20 +0000 Date: Sun, 17 Nov 2013 09:37:20 +0000 (UTC) From: "Stefan Bodewig (JIRA)" To: log4net-dev@logging.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13824781#comment-13824781 ] Stefan Bodewig commented on LOG4NET-376: ---------------------------------------- brought back the big lock with svn revision 1542664 I'll keep this ticket open as I'd like to look into different approaches to solve it in 1.3.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.2.13, 1.3.0 > > > 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 > { > ///

> /// 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) > ///

> [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 GetTimeStrings(StringBuilder sb1) > { > return sb1.ToString().Split(new[] {'\r', '\n'}, StringSplitOptions.RemoveEmptyEntries).ToList(); > } > private static void WriteAllTheTimes(IEnumerable 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)