gmane.comp.apache.logging.log4net.devel

[jira] [Commented] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dominik Psenner (JIRA — 2013-05-18T09:25:15

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

Dominik Psenner commented on LOG4NET-377:
-----------------------------------------

The official build is available only on apache.org
                

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

[jira] [Commented] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dan Händevik (JIRA — 2013-05-18T08:51:15

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

Dan Händevik commented on LOG4NET-377:
--------------------------------------

Correct me if I'm wrong, but the method that returns void is present in the 1.2.10 that i added from the nuget feed (http://nuget.org/packages/log4net/1.2.10). Is this not your official version of 1.2.10? is this a BETA version that has been put up on nuget?
                

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

[jira] [Commented] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dominik Psenner (JIRA — 2013-05-18T06:57:16

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

Dominik Psenner commented on LOG4NET-377:
-----------------------------------------

https://issues.apache.org/jira/browse/LOG4NET-2 states that this breaking change was done with revision 607475 and thus was released along with 1.2.10. Therefore you have been using log4net 1.2.9-BETA and, by being a beta, was subject to API breaking changes.
                

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

[jira] [Commented] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dan Händevik (JIRA — 2013-05-18T06:15:16

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

Dan Händevik commented on LOG4NET-377:
--------------------------------------

I cannot agree with your conclusion that this is expected behavior.
First of all, the version number does not indicate that the release contains any breaking changes. I guess that you don't conform to semantic versioning (http://semver.org/) but many .net libraries does and this is almost a standard now adays so I strongly suggest that you should look into that.
Secondly on your release notes page
 http://logging.apache.org/log4net/release/release-notes.html
you state that this is a buggix release. A bugfix release does not (in my opinion) introduces any breaking changes.
Third, on the same page you include a list of breaking changes but this list only contains one post and it is not this issue.

I cannot say that any of the above indicates to me that this is expected behavior.
Frankly, I doubted myself at first. I must have seen wrong.

It's not much work to keep a library backwards compatible.
Do not change any public signatures. If you invent a new signature (like adding a return value), give it a new name and make the old one obsolete instead.
This will keep backwards compability but issue a compiler warning that indicates the intended change for the user.
Removing obsolete code should only be done on a major release (when changing the major version number)

Log4net is a great .net library but if I cannot trust the stability of the releases then I cannot continue using the library in my own projects. My users can update their log4net nuget packages and that will break the dependency to mine.


/Dan

On 18 maj 2013, at 07:21, "Dominik Psenner (JIRA)" <jira< at >apache.org<mailto:jira< at >apache.org>> wrote:


    [ https://issues.apache.org/jira/browse/LOG4NET-377?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dominik Psenner closed LOG4NET-377.
-----------------------------------

   Resolution: Won't Fix
     Assignee: Dominik Psenner

This is expected behaviour and won't be fixed. If you want to move on you'll have to recompile your assembly that depends on log4net.

XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10
-----------------------------------------------------------------------

               Key: LOG4NET-377
               URL: https://issues.apache.org/jira/browse/LOG4NET-377
           Project: Log4net
        Issue Type: Bug
        Components: Core
  Affects Versions: 1.2.11
       Environment: .net 2 (and probably other versions as well
          Reporter: Dan Händevik
          Assignee: Dominik Psenner
          Priority: Blocker

The log4net.Config.XmlConfiguration method ConfigureAndWatch(FileInfo) differs from version 1.2.10 and 1.2.11.
In 10 it has void as return value and in 1.2.11 it returns an ICollection.
If I compile against 1.2.10 and then replaces the dll  with 1.2.11 and uses an assembly redirect to use the newer version I'll get a runtime error stating
Method not found: 'Void log4net.Config.XmlConfigurator.ConfigureAndWatch(System.IO.FileInfo)'.

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

                

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

[jira] [Closed] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dominik Psenner (JIRA — 2013-05-18T05:21:15

     [ https://issues.apache.org/jira/browse/LOG4NET-377?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dominik Psenner closed LOG4NET-377.
-----------------------------------

    Resolution: Won't Fix
      Assignee: Dominik Psenner

This is expected behaviour and won't be fixed. If you want to move on you'll have to recompile your assembly that depends on log4net.
                

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

[jira] [Created] (LOG4NET-377) XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10

Dan Händevik (JIRA — 2013-05-17T21:13:15

Dan Händevik created LOG4NET-377:
------------------------------------

             Summary: XmlConfigurator.ConfigureAndWatch is not backwards compatible to 1.2.10
                 Key: LOG4NET-377
                 URL: https://issues.apache.org/jira/browse/LOG4NET-377
             Project: Log4net
          Issue Type: Bug
          Components: Core
    Affects Versions: 1.2.11
         Environment: .net 2 (and probably other versions as well
            Reporter: Dan Händevik
            Priority: Blocker


The log4net.Config.XmlConfiguration method ConfigureAndWatch(FileInfo) differs from version 1.2.10 and 1.2.11.
In 10 it has void as return value and in 1.2.11 it returns an ICollection.

If I compile against 1.2.10 and then replaces the dll  with 1.2.11 and uses an assembly redirect to use the newer version I'll get a runtime error stating
Method not found: 'Void log4net.Config.XmlConfigurator.ConfigureAndWatch(System.IO.FileInfo)'.

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

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

Dominik Psenner (JIRA — 2013-05-17T06:41:15

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

Dominik Psenner commented on LOG4NET-376:
-----------------------------------------

Regarding ThreadStatic: I did not do performance timings, thus I do not know if it would perform better. My believe is that this attribute could tear down performance in heavily cross-threaded environments by practically disabling the cache. Generally I do not think it is wise to have code behaving one way in multi threading and another way in single threading. It makes the code terribly hard to maintain and therefore I would not want to take a foot on that road unless there are good arguments to do so.

Regarding the drop of static: changing the cache to be instance specific would practically make it ineffective since it would happen in every formatter instance whereas it needs to be done only once every second. So that would have a performance impact too which probably is bigger than a pure lock. The way Stefan fixed LOG4NET-323 seems to be perfectly fine to me.

It is widely known that thread safety does not come for free. If you believe that the performance impact is not neglectable I would like to encourage you to do some performance timings for these scenarios:

* "Rev 1483378" in Single Thread
* "Rev 1380139 + ThreadStatic" in Single Thread
* "Rev 1483378" in Multi Thread
* "Rev 1380139 + ThreadStatic" in Multi Thread

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

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

Stuart Lange (JIRA — 2013-05-16T21:43:16

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

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

I could also be convinced that locking the whole method is okay if all the static state were changed to instance state -- that would also have fixed LOG4NET-323, without requiring the dictionary of strings.
                

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

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

Stuart Lange (JIRA — 2013-05-16T21:41:16

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

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

Thanks for having a look.  I have a feeling that people will get concerned about the performance implications of locking the entire method.  I share that concern a bit, as this is a static lock object, so you are effectively synchronizing all calls to this method across the entire application.  Have you considered removing the locking and instead marking all the mutable static fields ThreadStatic? http://msdn.microsoft.com/en-us/library/system.threadstaticattribute.aspx
                

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

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

Dominik Psenner (JIRA — 2013-05-16T14:09:16

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

Dominik Psenner commented on LOG4NET-376:
-----------------------------------------

I've commited a second fix as 1483378. Please look at both revisions as being a single patch. Sorry for the noise.
                

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

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

Dominik Psenner (JIRA — 2013-05-16T14:05:16

     [ https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dominik Psenner resolved LOG4NET-376.
-------------------------------------

       Resolution: Fixed
    Fix Version/s: 1.2.12

I suspected that the lock in there would be sewed too tight. I've commited a fix as of revision 1483375. Can you confirm that it fixes your issue?
                

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

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

Dominik Psenner (JIRA — 2013-05-16T14:03:18

     [ 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
    

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

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

Stuart Lange (JIRA — 2013-05-16T13:55:15

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

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

Switching the static state to instance state would help a lot.  The race condition would still exist, but it would be restricted to a single instance.  It is much more reasonable to expect that a single instance will only see a monotonically increasing sequence of timestamps than it is to expect the whole application to process a monotonically increasing sequence of timestamps.
                

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

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

Stuart Lange (JIRA — 2013-05-16T13:27:18

[ 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.

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

Dominik Psenner (JIRA — 2013-05-14T06:23:16

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

Dominik Psenner commented on LOG4NET-376:
-----------------------------------------

Is this issue reproducable with one or more of the following formatters, too?

* AbsoluteTimeDateFormatter
* SimpleDateFormatter
* DateTimeDateFormatter
                

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

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

Johnson, Thomas — 2013-05-13T20:34:23

lol

-----Original Message-----
From: Johnson, Thomas [mailto:Thomas.Johnson< at >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:jira< at >apache.org] 
Sent: Monday, May 13, 2013 10:19 AM
To: log4net-dev< at >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.

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

Johnson, Thomas — 2013-05-13T19:49:00

unsubscribe

-----Original Message-----
From: Stuart Lange (JIRA) [mailto:jira< at >apache.org] 
Sent: Monday, May 13, 2013 10:19 AM
To: log4net-dev< at >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.

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

Stuart Lange (JIRA — 2013-05-13T16:19:16

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

[jira] [Closed] (LOG4NET-290) Add Lambda-based ILog-Extensions (embedded log.IsEnabled)

Dominik Psenner (JIRA — 2013-05-09T07:27:16

     [ https://issues.apache.org/jira/browse/LOG4NET-290?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dominik Psenner closed LOG4NET-290.
-----------------------------------


I'm glad we were able to resolve this issue. Thanks for your help. It wouldn't have been possible for me without you doing the documentation, therefore the Kudos go back to you!
                

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

[jira] [Commented] (LOG4NET-290) Add Lambda-based ILog-Extensions (embedded log.IsEnabled)

Pavel Nedoma (JIRA — 2013-05-08T21:27:16

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

Pavel Nedoma commented on LOG4NET-290:
--------------------------------------

Thank you for your cooperation. It seems that I can't update status of this issue, since I'm not the one who created it. But I agree with marking this issue as closed.
                

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

[jira] [Resolved] (LOG4NET-290) Add Lambda-based ILog-Extensions (embedded log.IsEnabled)

Dominik Psenner (JIRA — 2013-04-29T06:30:18

     [ https://issues.apache.org/jira/browse/LOG4NET-290?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dominik Psenner resolved LOG4NET-290.
-------------------------------------

       Resolution: Fixed
    Fix Version/s:     (was: 3.5)
                   1.2.12
         Assignee: Dominik Psenner

Committed fix as of revision: 1476902

Thanks for your help! You saved me a lot of time. :-) Feel free to close this issue if you think that there is no further work needed.
                

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