gmane.comp.apache.logging.log4net.devel

AW: log4net.dll version 1.2.10.0 (FileSystemWatcher objects)

Dominik Psenner — 2013-05-24T06:27:55

Good morning Yuvraj,

 

There's no way of being sure unless you have tried it out with your
application or a sample application that uses log4net in the same way you
do. Of course a sample application could do things faster than normal and in
an automated way so that the problem happens sooner and not only after 3
months. :)

 

So my testing setup would be two identical virtual machines. The first runs
the application against 1.2.10 and the second runs the application against
1.2.11. This way you can expect to see:

 

*         Virtual machine #1 leaks memory

*         Virtual machine #2 either does or doesn't leak memory

 

Cheers

 

Von: Yuvraj Raj [mailto:rajy< at >michaels.com] 
Gesendet: Donnerstag, 23. Mai 2013 20:27
An: log4net-dev< at >logging.apache.org
Betreff: log4net.dll version 1.2.10.0 (FileSystemWatcher objects)

 

Hi,

 

I am application developer team supporting.NET project in Michaels Stores.
We have been using log4net.dll version 1.2.10.0 for application logs for our
project. The application

log4net.dll version 1.2.10.0 (FileSystemWatcher objects)

Yuvraj Raj — 2013-05-23T18:26:50

Hi,

I am application developer team supporting.NET project in Michaels Stores. We have been using log4net.dll version 1.2.10.0 for application logs for our project. The application is implemented in .NET , C# with 3.5 framework.

Recently we have faced System.OutOfMemoryException exception thrown by the application. We have opened case with Microsoft.  Microsoft analyzed and said memory consumption is due to FileSystemWatcher objects used by log4net.Config.XmlConfigurator+ConfigureAndWatchHandler which are still alive and pinned objects.

From the memory dump, They found >2000 instances of log4net.Config.XmlConfigurator+ConfigureAndWatchHandler and the FileSystemWatcher objects created that contributed this issue. The issue is happening due to the fragmentation of Gen2 Heap. The reason for the fragmentation is the pinned System.IO.Overlapped objects used by FileSystemWatcher objects.

To resolve the memory  issue, we need to get rid of the fragmentation caused by pinned objects used by FileSystemWatcher obj

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

Dominik Psenner (JIRA — 2013-05-19T22:19:16

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

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

Yes, it seems 1.2.9 and 1.2.10 are downloadable from the archives and those downloads are marked incubation. The configuration and code is compatible, except the nitpicky detail of the XmlConfigurator. You are not the first who found that one out and won't be the last. However, there is no way to change a release that has been made and the API is fine like it is now.
                

--
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-19T18:13:15

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

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

So from what I can understand, there is no official version of log4net that is lower than 1.2.11? Both 1.2.9 and 1.2.10 are marked as incubator versions and code compiled against those versions are not compatible with 1.2.11?
                

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

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

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

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

[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

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