8 Replies Latest reply on Oct 25, 2019 3:28 PM by gary.stiek

    WF 12:  previous day log file overwritten with one line

    gary.stiek

      We have the following as our standard logging configuration from WF 12 to 18

       

              <subsystem xmlns="urn:jboss:domain:logging:4.0">

                  <console-handler name="CONSOLE">

                      <level name="INFO"/>

                      <formatter>

                          <named-formatter name="COLOR-PATTERN"/>

                      </formatter>

                  </console-handler>

                  <periodic-size-rotating-file-handler name="SIZETIME">

                      <level name="ALL"/>

                      <formatter>

                          <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n "/>

                      </formatter>

                      <file relative-to="jboss.server.log.dir" path="server.log"/>

                      <rotate-size value="20M"/>

                      <max-backup-index value="10"/>

                      <suffix value=".yyyy-MM-dd"/>

                  </periodic-size-rotating-file-handler>

                  <logger category="com.arjuna">

                      <level name="WARN"/>

                  </logger>

                  <logger category="org.jboss.as.config">

                      <level name="DEBUG"/>

                  </logger>

                  <logger category="sun.rmi">

                      <level name="WARN"/>

                  </logger>

                  <logger category="org.wildfly.security.access">

                      <level name="DEBUG"/>

                  </logger>

                  <root-logger>

                      <level name="INFO"/>

                      <handlers>

                          <handler name="CONSOLE"/>

                          <handler name="SIZETIME"/>

                      </handlers>

                  </root-logger>

                  <formatter name="PATTERN">

                      <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>

                  </formatter>

                  <formatter name="COLOR-PATTERN">

                      <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>

                  </formatter>

              </subsystem>

       

      We are finding that the log rotation at midnight is working as expected - the current log is renamed/moved to a file with the previous date (ie, server.log.2019-10-17).  And the current day's data is being written to server.log.  However, at some time around 5 AM or so, this previous day's log file is being overwritten with a single line entry:

       

      04:55:11,064 INFO  [org.jboss.modules] (main) JBoss Modules version 1.7.0.Final

       

      From running thread dumps, this is due to the "Periodic Recover" processes running

       

      "Periodic Recovery" #90 prio=5 os_prio=0 tid=0x0000000003d5c800 nid=0x12a6 in Object.wait() [0x00007f7c013b0000]

      java.lang.Thread.State: TIMED_WAITING (on object monitor)

      at java.lang.Object.wait(Native Method)

      at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doBackoffWait(PeriodicRecovery.java:663)

      at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:781)

      - locked <0x00000000c1be11a8> (a java.lang.Object)

      at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377)

       

      So that is it.  Whereas from midnight up until this process runs, there are several KBs of data from the previous day.  But once this process runs, that previous day's file is overwritten to only contain that one line.  81 bytes total.

       

      We also have the Security Manager enabled, if that makes any difference, although we don't see any additional violations being logged.

       

      Has anyone seen this or have any suggestions on what I should change in our configuration?  I am the engineer behind our WF builds, and this doesn't happen with just a simple test app installed.  But I am seeing this across many of our deployments for customer apps.

       

      Thank you!

        • 1. Re: WF 12:  previous day log file overwritten with one line
          brian.stansberry

          Is this a problem with WildFly 18?

          • 2. Re: WF 12:  previous day log file overwritten with one line
            jaikiran

            That's an odd one. Are there any CLI jobs that might be cron scheduled and are getting triggered? Either way, the fact that it's going to a log file which isn't "current" makes it look like some kind of bug somewhere. Plus the fact that it just logs a message that's coming from JBoss Modules, which seems to indicate that the module system is being initialized or the module logger being changed.

            • 3. Re: WF 12:  previous day log file overwritten with one line
              jaikiran

              Oh, I just noticed you mention WildFly 12 - so I have the same question as Brian. Is this reproducible in WildFly18?

              • 4. Re: WF 12:  previous day log file overwritten with one line
                gary.stiek

                Yes, we worked with the developers to upgrade their app to WF 18 and encountered the same issue.  So currently our logging config under WF 18 is

                 

                        <subsystem xmlns="urn:jboss:domain:logging:8.0">

                            <console-handler name="CONSOLE">

                                <level name="INFO"/>

                                <formatter>

                                    <named-formatter name="COLOR-PATTERN"/>

                                </formatter>

                            </console-handler>

                            <periodic-size-rotating-file-handler name="SIZETIME">

                                <formatter>

                                    <named-formatter name="PATTERN"/>

                                </formatter>

                                <file relative-to="jboss.server.log.dir" path="server.log"/>

                                <rotate-size value="20M"/>

                                <suffix value=".yyyy-MM-dd"/>

                            </periodic-size-rotating-file-handler>

                            <logger category="com.arjuna">

                                <level name="WARN"/>

                            </logger>

                            <logger category="io.jaegertracing.Configuration">

                                <level name="WARN"/>

                            </logger>

                            <logger category="org.jboss.as.config">

                                <level name="DEBUG"/>

                            </logger>

                            <logger category="sun.rmi">

                                <level name="WARN"/>

                            </logger>

                            <logger category="org.wildfly.security.access">

                                <level name="DEBUG"/>

                            </logger>

                            <root-logger>

                                <level name="INFO"/>

                                <handlers>

                                    <handler name="SIZETIME"/>

                                </handlers>

                            </root-logger>

                            <formatter name="PATTERN">

                                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>

                            </formatter>

                            <formatter name="COLOR-PATTERN">

                                <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>

                            </formatter>

                        </subsystem>

                 

                (we did switch to the named formatter "PATTERN" at some point in our development of WF standards)  And our one line is

                 

                2019-10-21 04:52:19,937 INFO  [org.jboss.modules] (main) JBoss Modules version 1.9.1.Final

                 

                One of their included jar files is Freemarker (https://freemarker.apache.org/) which appears to have some log4j and slf4j classes.  They had also included a log4j2.xml file with both a Console and RollingFileAppender defined.  We removed the log4j2.xml file with no luck.  Now on one server we are trying the WF settings to set add-logging-api-dependencies = false.  We have a second server where we are setting both add-logging-api-dependencies and use-deployment-logging-config to false.

                • 5. Re: WF 12:  previous day log file overwritten with one line
                  gary.stiek

                  Updating add-logging-api-dependencies and use-deployment-logging-config to false had no effect.  So we are still looking.  Right now I am going to have the app team put back in the log4j2.xml file but remove the CONSOLE handler.

                   

                  No CLI or any other automation running at that time.  The only thing that appears to be running is the Periodic Recovery thread.

                   

                  One other thing that I would mention is that to run, this application is requiring the following permissions:

                   

                                      <permission class="java.util.PropertyPermission" name="*" actions="read,write"/>

                                      <permission class="java.util.logging.LoggingPermission" name="control"/>

                                      <permission class="java.io.FilePermission" name="${jboss.server.log.dir}" actions="read"/>

                                      <permission class="java.io.FilePermission" name="${jboss.server.log.dir}/*" actions="read,write"/>

                   

                  The "control" requirement gets triggered by such lines in the application as

                   

                  private static final Logger LOG = Logger.getLogger(InternalRestResource.class.getName());

                  ...

                  LOG.info("Request to landing for " + userId);  <- triggers the exception

                  • 6. Re: WF 12:  previous day log file overwritten with one line
                    jaikiran

                    > private static final Logger LOG = Logger.getLogger

                     

                    What's the fully qualified class name of that Logger class? Can you paste the import statement of that one?

                    • 7. Re: WF 12:  previous day log file overwritten with one line
                      jaikiran

                      FWIW - So far, I don't think that the Periodic recovery thread is playing a role here.

                      • 8. Re: WF 12:  previous day log file overwritten with one line
                        gary.stiek

                        For imports they have

                         

                        import java.util.logging.Level;

                        import java.util.logging.Logger;

                         

                        From further testing, it seems like we have two ways to deal with this:

                         

                        1.  Set <use-deployment-logging-config value="false"/> and delete their log4j2.xml file (not sure yet that the delete is necessary, but it feels cleaner)

                        2.  Edit their log4j2.xml to remove the CONSOLE appender.  If we just remove the file entirely without also setting use-deployment-logging-config to false things end up just as bad.  The RollingFile is never written and appears to be ignored.

                         

                        Their log4j2.xml:

                         

                        <?xml version="1.0" encoding="UTF-8"?>

                        <Configuration>

                          <Appenders>

                         

                         

                            <!-- Console Appender -->

                            <Console name="Console" target="SYSTEM_OUT">

                              <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />

                            </Console>

                         

                         

                            <!-- Daily Rolling File Appender -->

                            <RollingFile name="RollingFile">

                              <FileName>C:/app_log/app.log</FileName>

                              <FilePattern>C:/app_log/daily_logs/%d{yyyy-MM-dd}.log.zip</FilePattern>

                              <PatternLayout>

                                <Pattern>%d{yyyy-MMM-dd HH:mm:ss a} [%t] %-5level %logger{36} - %msg%n</Pattern>

                              </PatternLayout>

                              <Policies>

                                <TimeBasedTriggeringPolicy interval="1" modulate="true" />

                              </Policies>

                              <DefaultRolloverStrategy max="5" />

                            </RollingFile>

                         

                         

                          </Appenders>

                          <Loggers>

                            <Logger name="com.app" level="debug" additivity="false">

                              <AppenderRef ref="RollingFile" />

                              <AppenderRef ref="Console" />

                            </Logger>

                            <Root level="trace">

                              <AppenderRef ref="Console" />

                            </Root>

                          </Loggers>

                        </Configuration>

                         

                        At this point I wish I could track down what is even interpreting this file.  From what research I have done, WF doesn't support log4j2 and so should ignore this file.  And the application is not including any log4j2 components at all.  But if I remove all of the references to CONSOLE (the actual appender and the 2 references to it) the logs appear to roll as expected.  We have this edited log4j2.xml file in their CAT systems for one day with success.  We will see if this continues over the weekend.