Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-117

Double-rollover occuring, loosing logs

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Implemented
    • 2.0-alpha2
    • 2.0-beta2
    • Appenders, Core
    • None
    • Java 1.6.x
      Tomcat 7.0.x

    Description

      I've noticed an interesting double-rollover happening, which I think is related to having two references to the same appender. It seems to keep track of the triggering events for each one separately or something.

      Backstory:

      The general setup in this case is that I have some JSP based websites running under Tomcat. I also have a library of utility code that they all share. Some of the utilities are used during the startup phase, and as a result the logging is a disparate mess due to different code being loaded by different classloaders and so on.

      My eventual solution to all this, which works well, is to have all Loggers managed under a single centralized configuration and under the common classloader, including Tomcat's logging itself. I then use a servlet filter on each webapp to set a value in the MDC/ThreadContext, and a Routing logger to send the webapp-generated log events (be it from a JSP or a shared utility library) to appropriate location. Anything else is just dumped in the central log file.

      Also, the JSP code still has several legacy components which are using old System.out.println() style calls that are still being replaced with proper logging calls via log4j. In the meantime, I still want to capture those events inline, so I use Tomcat's swallowOutput feature to have it intercept them.

      Because the System.out calls are handled by the container directly, they don't carry the MDC/ThreadContext key. As a result, I have to manually route them to the appropriate appender. Fortunately Tomcat assigns a logger name that is webapp specific, so I have something to identify them by.

      Behavior:

      Since I'm doing daily rolling, set system time to 11:59 PM

      Start server up

      Hit a test JSP which performs a log4j call, see entry in the webapp specific log file

      Hit another test JSP which performs a System.out call, see entry in the same webapp specific log file

      Wait for a minute so that system time is now in next day

      Hit one of the test JSP files again

      See logfile rollover happen, old file archived, and entry in the newly created file

      Hit that same test JSP again, entry just below previous

      (all good so far)

      Hit the other test JSP

      See logfile rollover happen again (!!), entry in the newly created file, and the recently-created file is archived which overwrites the properly archived one in the process (!!)

      (I've lost a whole day of logs, this is very bad)

      Further hits to either JSP continue in current file as they should, until the next day's double-rollover happens

      Attached is my (slightly simplified for readability and test case purposes) config file.

      Attachments

        1. doubleroll.xml
          2 kB
          David Johle

        Activity

          People

            Unassigned Unassigned
            djohle David Johle
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: