Log4net
  1. Log4net
  2. LOG4NET-158

XMLConfigurator.ConfigureAndWatch() leaks resources if called multiple times

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.2.10
    • Fix Version/s: 1.2.11
    • Component/s: Other
    • Labels:
      None
    • Environment:
      Windows Server 2003, Windows XP

      Description

      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.

        Activity

        Hide
        Ron Grabowski added a comment -

        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); }
        Show
        Ron Grabowski added a comment - 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); }
        Hide
        Strategic Insurance Software added a comment -

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

        Show
        Strategic Insurance Software added a comment - 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).
        Hide
        Ron Grabowski added a comment -

        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?

        Show
        Ron Grabowski added a comment - 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?
        Hide
        Ron Grabowski added a comment -

        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.

        Show
        Ron Grabowski added a comment - 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.
        Hide
        Ron Grabowski added a comment -

        Made ConfigureAndWatchHandler implement IDiposable in order to properly dispose of handles held by the FileSystemWatcher and Timer classes.

        Show
        Ron Grabowski added a comment - Made ConfigureAndWatchHandler implement IDiposable in order to properly dispose of handles held by the FileSystemWatcher and Timer classes.
        Hide
        Strategic Insurance Software added a comment -

        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.

        Show
        Strategic Insurance Software added a comment - 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.
        Hide
        Emil Vladov added a comment -

        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.

        Show
        Emil Vladov added a comment - 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.
        Hide
        Ron Grabowski added a comment -

        Fixed in r688527

        Show
        Ron Grabowski added a comment - Fixed in r688527

          People

          • Assignee:
            Unassigned
            Reporter:
            Strategic Insurance Software
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development