WF 12: previous day log file overwritten with one line
gary.stiek Oct 18, 2019 12:48 PMWe 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!