Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-10018

logging FileAppender does not close files after use

    Details

    • Type: Bug
    • Status: To Do
    • Resolution: Unresolved
    • Fix Version/s: None
    • Component/s: log
    • Labels:
      None
    • Team:
      Data Access and Database

      Description

      Running the attached test file exposes a problem with using FileAppender.

      $ python small.py
      .File open: /home/srp/mine/legacy-ctrl_events/tests/test.log
      F.
      ======================================================================
      FAIL: testFileDescriptorLeaks (__main__.smallMemoryTestCase)
      ----------------------------------------------------------------------
      Traceback (most recent call last):
        File "/scratch/srp/lsstsw/stack/Linux64/utils/13.0/python/lsst/utils/tests.py", line 178, in testFileDescriptorLeaks
          self.fail("Failed to close %d file%s" % (len(diff), "s" if len(diff) != 1 else ""))
      AssertionError: Failed to close 1 file
      

      As a side note, since the file isn't flushed at any point, the test.log file ends up being empty. edit: this is because it was being sent to trace, not info.

      The tests in lsst.log don't use the lsst.utils.tests framework so this bug wasn't exposed. Additionally, the test that is there in testLog.py names the file "

      {0}

      " - I'm not sure what this was supposed to be

        Attachments

          Activity

          Hide
          swinbank John Swinbank added a comment - - edited

          Note that files will always be closed on program exit: the operating system takes care of that for you. The issue here is that the log system opens a file during test execution, and that file isn't closed again when that particular test is finished. The test suite interprets as a leak. I've updated the title of this ticket to reflect that.

          I suspect that this is actually a problem with the test in question: I don't think a well formed unit test should modify its environment. I therefore agree that leaving files open on test exit which weren't open when the test started is a failure. That means: if you open a log file during a test, you'd better close it too, or your test is wrong.

          However, I'm not sure how easy it is to meet that goal. Maybe Hsin-Fang Chiang could comment?

          Show
          swinbank John Swinbank added a comment - - edited Note that files will always be closed on program exit: the operating system takes care of that for you. The issue here is that the log system opens a file during test execution, and that file isn't closed again when that particular test is finished. The test suite interprets as a leak. I've updated the title of this ticket to reflect that. I suspect that this is actually a problem with the test in question: I don't think a well formed unit test should modify its environment. I therefore agree that leaving files open on test exit which weren't open when the test started is a failure. That means: if you open a log file during a test, you'd better close it too, or your test is wrong. However, I'm not sure how easy it is to meet that goal. Maybe Hsin-Fang Chiang could comment?
          Hide
          swinbank John Swinbank added a comment -

          Setting team to DAX because I believe the logging system is a SLAC production. Pinging Fritz Mueller to let him know.

          Show
          swinbank John Swinbank added a comment - Setting team to DAX because I believe the logging system is a SLAC production. Pinging Fritz Mueller to let him know.
          Hide
          tjenness Tim Jenness added a comment -

          I agree with John Swinbank. Consider the (not unreasonable) case where we run all tests in a single process. These will start failing once we run out of file descriptors.

          Show
          tjenness Tim Jenness added a comment - I agree with John Swinbank . Consider the (not unreasonable) case where we run all tests in a single process. These will start failing once we run out of file descriptors.
          Hide
          salnikov Andy Salnikov added a comment -

          I'm not sure I agree with the above statements - it seems to be based on assumption that test case has control over all files/sockets that are open on its behalf. Leaking file descriptors are bad of course, but only if they are indeed leaking. Logging does not leak, it's using a single file descriptor which will be closed when whole application terminates and it was designed to behave that way. There are still issues with the logging use in test (the attached test is dumb but there may be more realistic cases) which need to take into account that logging is a shared resource and behave nicely w.r.t. to other unit tests. What that probably translates to is that if unit test need special non-default logging configuration then it should set it int the setUp() method and revert back to default configuration in tearDown().

          And I don't think this problem is unique to logging, I can imagine other cases, e.g. database (or web service) access which uses smart connection pooling that does not necessarily terminates physical connections immediately.

          Show
          salnikov Andy Salnikov added a comment - I'm not sure I agree with the above statements - it seems to be based on assumption that test case has control over all files/sockets that are open on its behalf. Leaking file descriptors are bad of course, but only if they are indeed leaking. Logging does not leak, it's using a single file descriptor which will be closed when whole application terminates and it was designed to behave that way. There are still issues with the logging use in test (the attached test is dumb but there may be more realistic cases) which need to take into account that logging is a shared resource and behave nicely w.r.t. to other unit tests. What that probably translates to is that if unit test need special non-default logging configuration then it should set it int the setUp() method and revert back to default configuration in tearDown() . And I don't think this problem is unique to logging, I can imagine other cases, e.g. database (or web service) access which uses smart connection pooling that does not necessarily terminates physical connections immediately.
          Hide
          spietrowicz Steve Pietrowicz added a comment -

          I looked into fairly quickly last week, and there is indeed a shutdown() method that preforms this function in log4cxx, which even has a warning that some appenders need to be closed before the application exits or pending logging events may be lost (this is for SocketAppender and AsyncAppender, as an example). Third party users that might implement something that uses a SocketAppender would lose the data.

          I'm not sure if this is done through LogManager in the lsst c++ code or how this would need to be done, since I haven't used log4cxx much.

          Show
          spietrowicz Steve Pietrowicz added a comment - I looked into fairly quickly last week, and there is indeed a shutdown() method that preforms this function in log4cxx, which even has a warning that some appenders need to be closed before the application exits or pending logging events may be lost (this is for SocketAppender and AsyncAppender, as an example). Third party users that might implement something that uses a SocketAppender would lose the data. I'm not sure if this is done through LogManager in the lsst c++ code or how this would need to be done, since I haven't used log4cxx much.
          Hide
          salnikov Andy Salnikov added a comment -

          Steve Pietrowicz, indeed there is a shutdown() method but it's not entirely relevant for this discussion. I guess for unit test the ideology is that they should leave things in exactly same state as it was before execution of a unit test, including various shared state such as logging configuration. Even though I'm not sure it's possible in general, for the logging it would mean that unit tests either should not change logging configuration at all, or if they change it they should restore it. Logging currently does not support configuration save/restore, the only way to restore currently is to put it into default configuration which may be a reasonable approximation for unit tests. And I'm not 100% sure that it is guaranteed to reclaim all file descriptors but it probably should.

          Show
          salnikov Andy Salnikov added a comment - Steve Pietrowicz , indeed there is a shutdown() method but it's not entirely relevant for this discussion. I guess for unit test the ideology is that they should leave things in exactly same state as it was before execution of a unit test, including various shared state such as logging configuration. Even though I'm not sure it's possible in general, for the logging it would mean that unit tests either should not change logging configuration at all, or if they change it they should restore it. Logging currently does not support configuration save/restore, the only way to restore currently is to put it into default configuration which may be a reasonable approximation for unit tests. And I'm not 100% sure that it is guaranteed to reclaim all file descriptors but it probably should.
          Hide
          spietrowicz Steve Pietrowicz added a comment -

          I think it's relevant for the overall problem. The unit test just points out that the file descriptor was open in the first place; I'm less worried about the unit test itself and more worried we're leaving file descriptors open, and no way of closing them. For FileAppender that happens to work out; for other types of Appenders data would be lost.

          Show
          spietrowicz Steve Pietrowicz added a comment - I think it's relevant for the overall problem. The unit test just points out that the file descriptor was open in the first place; I'm less worried about the unit test itself and more worried we're leaving file descriptors open, and no way of closing them. For FileAppender that happens to work out; for other types of Appenders data would be lost.

            People

            • Assignee:
              Unassigned
              Reporter:
              spietrowicz Steve Pietrowicz
              Watchers:
              Andy Salnikov, John Swinbank, Perry Gee, Steve Pietrowicz, Tim Jenness
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:

                Summary Panel