Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-988

logback does not always close log files

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • 1.1.2
    • logback-core
    • None
    • Windows 7

    Description

      I want to use the SiftingAppender logback library to write log messages to two different log files. Each pass shall write to different (custom-specified) file names.

      The problem is that the log files are not closed after the pass, so under Windows it is not possible to delete them. The documentation says that each file will be automatically closed after 30 min. of inactivity, but this does not seem to be the case. The files are still open even after a day.
      Note that under Linux the log files aren't closed either, but they are made invisible on delete so it just looks as if they were in fact deleted but they are not.

      Here's my code:

      // get the log file names
      ...
      
      // set up MDC
      
      MDC.put(Constants.CLIENTLOGGER_NAME, clientLogPath);
      MDC.put(Constants.ADMINLOGGER_NAME, adminLogPath);
      
      // run the job with some client and admin log messages
      ...
      
      // close the log files
      Marker marker = MarkerFactory.getMarker("Finalize");
      marker.add(ClassicConstants.FINALIZE_SESSION_MARKER);
      clientlog.info(marker, "");
      adminlog.info(marker, "");
      

      First problem:

      The clientlog.info call will finally call genericStaleComponentRemover(lingerersMap, now, byLingering). My understanding of this code is: Close the file after 10 seconds (return ((entry.timestamp + LINGERING_TIMEOUT) < now);)

      Note that the file is not closed on the first clientlog.info call because the timeout has not exceeded. Since this is the last step in my batch processing this means that all log files of the last batch are never closed.

      Second problem:

      As a workaround I called Thread.sleep(11000) followed by a dummy clientlog.info but the close call was not triggered either. It turned out that entry.timestamp always holds the current time so the statement above will never be true. This if-statement will never work.

      Third problem:

      I then modified the if-statement to always be true and found out that now my clientlog file was in fact being closed but not the adminlog file. The reason for this is that the function isTooSoonForRemovalIteration() makes sure that only one log file per second can be closed. Which is not the case with my program, as the markers for both files are written at the same time and there will not be another write to the log file. I worked around this problem by inserting a Thread.sleep(1100) but this is far from elegant.

      Please advise whether this is a bug or designed this way, and if the latter, what is the correct way to code my requirement. I simply want to log into two different log files and not having lots of open files after a while.

      Attachments

        Activity

          People

            logback-dev Logback dev list
            schirmacher Arne Schirmacher
            Votes:
            4 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated: