You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-dev@logging.apache.org by "Strategic Insurance Software (JIRA)" <ji...@apache.org> on 2008/05/28 20:35:45 UTC
[jira] Created: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
----------------------------------------------------------------------------
Key: LOG4NET-158
URL: https://issues.apache.org/jira/browse/LOG4NET-158
Project: Log4net
Issue Type: Bug
Components: Other
Affects Versions: 1.2.10
Environment: Windows Server 2003, Windows XP
Reporter: Strategic Insurance Software
If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Emil Vladov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12606342#action_12606342 ]
Emil Vladov commented on LOG4NET-158:
-------------------------------------
I've added comment to a similar cxx issue:
https://issues.apache.org/jira/browse/LOGCXX-166
but as it is closed not sure if anyone will read it :)
Basically the same never destroyed watcher causes access violations under Win32 as the watcher thread isn't stopped after the log4cxx DLL unloads.
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
> Fix For: 1.2.11
>
> Attachments: Release_handles_in_ConfigureAndWatch.patch
>
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ron Grabowski updated LOG4NET-158:
----------------------------------
Fix Version/s: 1.2.11
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
> Fix For: 1.2.11
>
> Attachments: Release_handles_in_ConfigureAndWatch.patch
>
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12600924#action_12600924 ]
Ron Grabowski commented on LOG4NET-158:
---------------------------------------
I thought that a new FileSystemWatcher was created each time the config file changed. That's not how the current implementation works.
If it were the case then we could dispose the FileSystemWatcher and then call InternalConfigureAndWatch again:
private void OnWatchedFileChange(object state)
{
// release resources being watched
FileSystemWatcher watcher = (FileSystemWatcher)state;
watcher.EnableRaisingEvents = false;
watcher.Dispose();
// re-create a new FileSystemWatcher using m_configFile
// m_repository.ShutDown(); ???
XmlConfigurator.InternalConfigureAndWatch(m_repository, m_configFile);
}
I'm not too worried about the cost of creating a new FileSystemWatcher because the config file isn't something that is likely to change a lot in a very small time period.
Doing it that way we shouldn't have to introduce any other variables or make ConfigureAndWatchHandler implement IDisposable.
I don't think your #3 step would work because log4net supports multiple repositories. Its possible, albeit a bit unlikely, that someone could have two repositories running with each one having a file watch on a separate config file.
When configuring the repository over again I'd like to start from a clean slate each time and not have to worry about cleaning up from the last instance. Speaking of cleaning up...I suspect ShutDown() isn't being called on the repository before reconfiguring it to support log4net's "merge" functionality of the new config file. I don't know how well the "merge" functionality works to be quite honest. I think there is an open ticket on it.
Thoughts?
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Strategic Insurance Software (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12601156#action_12601156 ]
Strategic Insurance Software commented on LOG4NET-158:
------------------------------------------------------
The test case you posted accurately reflects the sequence of steps that got our servers into trouble, so if the solution passes that test, everything should be good.
Thank you for your prompt attention to this issue.
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
> Attachments: Release_handles_in_ConfigureAndWatch.patch
>
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ron Grabowski updated LOG4NET-158:
----------------------------------
Attachment: Release_handles_in_ConfigureAndWatch.patch
Made ConfigureAndWatchHandler implement IDiposable in order to properly dispose of handles held by the FileSystemWatcher and Timer classes.
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
> Attachments: Release_handles_in_ConfigureAndWatch.patch
>
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Strategic Insurance Software (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12600904#action_12600904 ]
Strategic Insurance Software commented on LOG4NET-158:
------------------------------------------------------
Ron Grabowski said:
"Have you had a chance to test my solution to your log4net issue?"
I'm just now for the first time looking at the source to XmlConfigurator. I've not had a chance to test the proposed fix specifically, and I'm not an expert on this source code, but unless I'm missing something, this would not fix the issue, as OnWatchedFileChange would only be called if the configuration file actually changes, and would not be called when a second/third/nth FileSystemWatcher is created.
The following might be a possible fix based on my reading of the code:
1. Establish an instance variable within the ConfigureAndWatchHandler class to hold a reference to the created FileSystemWatcher.
2. Implement the IDisposable interface/pattern on the ConfigureAndWatchHandler class. Within its implementation of Dispose, call the FileSystemWatcher's Dispose() method.
3. Establish a static variable in XmlConfigurator to hold a reference to the ConfigureAndWatchHandler that is created in ConfigureAndWatch().
4. In ConfigureAndWatch, add code prior to the creation of the ConfigureAndWatchHandler to call .Dispose() for the previously created ConfigureAndWatchHandler, if one was created previously.
Ron Grabowski said:
"How did you detect the file handler lock?"
To clarify, we're talking about file handles, not locks. We have a series of server applications (ASP.NET web service, plus supporting Windows Services), and while we have been leveraging log4net for a while, our recent release made much more extensive use of logging. The apps would leak to the point of needing to be restarted several times daily. We used the sysinternals tools to nail down that we were leaking file handles, and found that all of the leaked handles were pointing to the folder containing our log4net configuration file. Upon further investigation, we found that we were calling XmlConfiguration.ConfigureAndWatch() every time we created an instance of our internal logging class, which wraps our access to log4net. We changed our app to only call ConfigureAndWatch() once, and our leak went away.
Ron Grabowski said:
"What use case to have for calling ConfigureAndWatch multiple times? Its usually only called once when the application starts."
It's true enough that we should have only been calling this method once, and our code has been corrected to reflect that. We've effectively worked around the issue, but I still wanted to report it so that in future releases, multiple calls to ConfigureAndWatch() would be more harmless (aside from the obvious performance implications).
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12601148#action_12601148 ]
Ron Grabowski commented on LOG4NET-158:
---------------------------------------
This was the test case I used to see if the call to Dispose was releasing the handle (Handle column in Process Explorer):
// this is really bad...don't do it!
while (true)
{
Thread.Sleep(1000);
log4net.Config.XmlConfigurator.ConfigureAndWatch(new FileInfo("c:\\log4net.config"));
ILog programLog = LogManager.GetLogger(typeof(Program));
programLog.Info("Hello World");
}
The handle was still being leaked when I use various combinations of this code:
private void OnWatchedFileChange(object state)
{
// release resources being watched
FileSystemWatcher watcher = (FileSystemWatcher)state;
watcher.EnableRaisingEvents = false;
watcher.Dispose();
XmlConfigurator.InternalConfigure(m_repository, m_configFile);
}
I also tried hooking into the repository's ShutDownEvent and disposing the FileSystemWatcher there too. None of those seemed to work.
If used properly (i.e. calling ConfigureAndWatch once) there are no handle leaks...even if there are lots of changes detected on the file.
I implemented your solution and didn't see any leaks (uploaded patch to this issue). I suppose we could apply it just to be safe.
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12600643#action_12600643 ]
Ron Grabowski commented on LOG4NET-158:
---------------------------------------
Do we just need to forcible Dispose the watcher since we're not using it anymore?
private void OnWatchedFileChange(object state)
{
// release resources being watched
FileSystemWatcher watcher = (FileSystemWatcher)state;
watcher.EnableRaisingEvents = false;
watcher.Dispose();
XmlConfigurator.InternalConfigure(m_repository, m_configFile);
}
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Resolved: (LOG4NET-158) XMLConfigurator.ConfigureAndWatch()
leaks resources if called multiple times
Posted by "Ron Grabowski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/LOG4NET-158?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ron Grabowski resolved LOG4NET-158.
-----------------------------------
Resolution: Fixed
Fixed in r688527
> XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times
> ----------------------------------------------------------------------------
>
> Key: LOG4NET-158
> URL: https://issues.apache.org/jira/browse/LOG4NET-158
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 1.2.10
> Environment: Windows Server 2003, Windows XP
> Reporter: Strategic Insurance Software
> Fix For: 1.2.11
>
> Attachments: Release_handles_in_ConfigureAndWatch.patch
>
>
> If XMLConfigurator.ConfigureAndWatch() is called multiple times within an AppDomain, each time it is called it leaks a Win32 file handle (possibly from a FileSystemWatcher object not being disposed?) to the folder containing the previous configuration file it was watching.
> Desired behavior would be to release the handle to the folder containing the previous configuration file.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.