You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Skye Antinozzi <an...@morris.umn.edu> on 2018/10/01 23:32:39 UTC
Rolled logs are sometimes empty
Hello!
We are using a RollingRandomAccessFile appender with a 5 minute cron
rollover schedule. On rare occasion logs stop being output after rolling
and seem to not recover until the application restarts.
We run with a somewhat complicated log configuration, using the following:
* Async appender
* Marker filters
* Name filters
* Multiple log files
* JSON output
* cron rollover schedule
We use log markers to filter our messages out to their own file. We use a
log name filter to filter a statistics class to its own file.
We run our application(s) daily and quite constantly, yet, the problem
seems to occur anywhere from multiple times a day to spanning a few days
between occurrences. When the problem does occur, it seems that it can be
corrected upon restarting the application.
Here is our log4j2.xml:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
<Properties>
<Property name="cronRolloverSchedule">0 */5 * * * ?</Property>
<Property name="logDir">./logs</Property>
<Property name="rolloverLogDir">./logs_backup</Property>
<Property name="logPattern">%d{ISO8601}{UTC}Z %-5level [%thread] %logger -
%message%n</Property>
<Property name="messagePattern">%d{ISO8601}{UTC}Z %message%n</Property>
</Properties>
<Appenders>
<RollingRandomAccessFile
name="Main"
fileName="${logDir}/myapp.json.log"
filePattern="${rolloverLogDir}/myapp.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
<JsonLayout
properties="true"
complete="true" />
<Policies>
<CronTriggeringPolicy
schedule="${cronRolloverSchedule}"
evaluateOnStartup="true" />
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile
name="Statistics"
fileName="${logDir}/myapp.stats.json.log"
filePattern="${rolloverLogDir}/myapp.stats.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
<JsonLayout
properties="true"
complete="true" />
<Policies>
<CronTriggeringPolicy
schedule="${cronRolloverSchedule}"
evaluateOnStartup="true" />
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile
name="Message"
fileName="${logDir}/myapp-messages.json.log"
filePattern="${rolloverLogDir}/myapp-messages.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
<JsonLayout
properties="true"
complete="true" />
<Policies>
<CronTriggeringPolicy
schedule="${cronRolloverSchedule}"
evaluateOnStartup="true" />
</Policies>
</RollingRandomAccessFile>
</Appenders>
<Loggers>
<AsyncRoot level="trace">
<AppenderRef ref="Main">
<Filters>
<MarkerFilter
marker="MESSAGE"
onMatch="DENY"
onMismatch="NEUTRAL" />
<MarkerFilter
marker="EVENT_STATISTICS"
onMatch="DENY"
onMismatch="NEUTRAL" />
</Filters>
</AppenderRef>
<AppenderRef ref="Message">
<Filters>
<MarkerFilter
marker="MESSAGE"
onMatch="ACCEPT"
onMismatch="DENY" />
<MarkerFilter
marker="EVENT_STATISTICS"
onMatch="DENY"
onMismatch="NEUTRAL" />
</Filters>
</AppenderRef>
</AsyncRoot>
<AsyncLogger
name="com.myapp.EventStatistics"
level="INFO">
<AppenderRef ref="Statistics" />
</AsyncLogger>
</Loggers>
</Configuration>
Thanks for the help!
- Skye
Re: Rolled logs are sometimes empty
Posted by Ralph Goers <ra...@dslextreme.com>.
Unfortunately, I have not heard of anyone else experiencing the same (or similar) problem.
Ralph
> On Oct 3, 2018, at 11:45 AM, Skye Antinozzi <an...@morris.umn.edu> wrote:
>
> We are using Red Hat Enterprise Linux Server release 7.2 and Log4j version
> 2.11.0. Unfortunately, we have not found any related output in stdout or
> stderr.
>
> We are suspicious that the async logger may be the culprit behind this
> issue so we are running tests with a standard sync logger (by changing
> AsyncLogger and AsyncRoot to Logger and Root, respectively). Do we know if
> any other Log4j users have had similar issues with async logging?
>
> Thanks.
>
> On Tue, Oct 2, 2018 at 9:30 AM Ralph Goers <ra...@dslextreme.com>
> wrote:
>
>> While I don’t see anything technically wrong with your configuration you
>> could probably simplify it. If all statistics are produced using the
>> com.myapp.EventStatistics logger you can add additivity=“false” to that
>> logger to prevent the events form also being handled by the root logger. I
>> would presume you could then remove the statistics filters.
>>
>> What OS is this running on and what version of Log4j? I assume you have
>> checked stdout/stderr for any messages that might be printed by Log4j?
>>
>> Ralph
>>
>>> On Oct 1, 2018, at 4:32 PM, Skye Antinozzi <an...@morris.umn.edu>
>> wrote:
>>>
>>> Hello!
>>>
>>> We are using a RollingRandomAccessFile appender with a 5 minute cron
>>> rollover schedule. On rare occasion logs stop being output after rolling
>>> and seem to not recover until the application restarts.
>>>
>>> We run with a somewhat complicated log configuration, using the
>> following:
>>> * Async appender
>>> * Marker filters
>>> * Name filters
>>> * Multiple log files
>>> * JSON output
>>> * cron rollover schedule
>>>
>>> We use log markers to filter our messages out to their own file. We use a
>>> log name filter to filter a statistics class to its own file.
>>>
>>> We run our application(s) daily and quite constantly, yet, the problem
>>> seems to occur anywhere from multiple times a day to spanning a few days
>>> between occurrences. When the problem does occur, it seems that it can be
>>> corrected upon restarting the application.
>>>
>>> Here is our log4j2.xml:
>>>
>>> <?xml version="1.0" encoding="UTF-8"?>
>>> <Configuration status="INFO">
>>> <Properties>
>>> <Property name="cronRolloverSchedule">0 */5 * * * ?</Property>
>>> <Property name="logDir">./logs</Property>
>>> <Property name="rolloverLogDir">./logs_backup</Property>
>>> <Property name="logPattern">%d{ISO8601}{UTC}Z %-5level [%thread] %logger
>> -
>>> %message%n</Property>
>>> <Property name="messagePattern">%d{ISO8601}{UTC}Z %message%n</Property>
>>> </Properties>
>>> <Appenders>
>>> <RollingRandomAccessFile
>>> name="Main"
>>> fileName="${logDir}/myapp.json.log"
>>> filePattern="${rolloverLogDir}/myapp.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
>>> <JsonLayout
>>> properties="true"
>>> complete="true" />
>>> <Policies>
>>> <CronTriggeringPolicy
>>> schedule="${cronRolloverSchedule}"
>>> evaluateOnStartup="true" />
>>> </Policies>
>>> </RollingRandomAccessFile>
>>> <RollingRandomAccessFile
>>> name="Statistics"
>>> fileName="${logDir}/myapp.stats.json.log"
>>>
>> filePattern="${rolloverLogDir}/myapp.stats.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
>>> <JsonLayout
>>> properties="true"
>>> complete="true" />
>>> <Policies>
>>> <CronTriggeringPolicy
>>> schedule="${cronRolloverSchedule}"
>>> evaluateOnStartup="true" />
>>> </Policies>
>>> </RollingRandomAccessFile>
>>> <RollingRandomAccessFile
>>> name="Message"
>>> fileName="${logDir}/myapp-messages.json.log"
>>>
>> filePattern="${rolloverLogDir}/myapp-messages.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
>>> <JsonLayout
>>> properties="true"
>>> complete="true" />
>>> <Policies>
>>> <CronTriggeringPolicy
>>> schedule="${cronRolloverSchedule}"
>>> evaluateOnStartup="true" />
>>> </Policies>
>>> </RollingRandomAccessFile>
>>> </Appenders>
>>> <Loggers>
>>> <AsyncRoot level="trace">
>>> <AppenderRef ref="Main">
>>> <Filters>
>>> <MarkerFilter
>>> marker="MESSAGE"
>>> onMatch="DENY"
>>> onMismatch="NEUTRAL" />
>>> <MarkerFilter
>>> marker="EVENT_STATISTICS"
>>> onMatch="DENY"
>>> onMismatch="NEUTRAL" />
>>> </Filters>
>>> </AppenderRef>
>>> <AppenderRef ref="Message">
>>> <Filters>
>>> <MarkerFilter
>>> marker="MESSAGE"
>>> onMatch="ACCEPT"
>>> onMismatch="DENY" />
>>> <MarkerFilter
>>> marker="EVENT_STATISTICS"
>>> onMatch="DENY"
>>> onMismatch="NEUTRAL" />
>>> </Filters>
>>> </AppenderRef>
>>> </AsyncRoot>
>>> <AsyncLogger
>>> name="com.myapp.EventStatistics"
>>> level="INFO">
>>> <AppenderRef ref="Statistics" />
>>> </AsyncLogger>
>>> </Loggers>
>>> </Configuration>
>>>
>>> Thanks for the help!
>>>
>>> - Skye
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Rolled logs are sometimes empty
Posted by Skye Antinozzi <an...@morris.umn.edu>.
We are using Red Hat Enterprise Linux Server release 7.2 and Log4j version
2.11.0. Unfortunately, we have not found any related output in stdout or
stderr.
We are suspicious that the async logger may be the culprit behind this
issue so we are running tests with a standard sync logger (by changing
AsyncLogger and AsyncRoot to Logger and Root, respectively). Do we know if
any other Log4j users have had similar issues with async logging?
Thanks.
On Tue, Oct 2, 2018 at 9:30 AM Ralph Goers <ra...@dslextreme.com>
wrote:
> While I don’t see anything technically wrong with your configuration you
> could probably simplify it. If all statistics are produced using the
> com.myapp.EventStatistics logger you can add additivity=“false” to that
> logger to prevent the events form also being handled by the root logger. I
> would presume you could then remove the statistics filters.
>
> What OS is this running on and what version of Log4j? I assume you have
> checked stdout/stderr for any messages that might be printed by Log4j?
>
> Ralph
>
> > On Oct 1, 2018, at 4:32 PM, Skye Antinozzi <an...@morris.umn.edu>
> wrote:
> >
> > Hello!
> >
> > We are using a RollingRandomAccessFile appender with a 5 minute cron
> > rollover schedule. On rare occasion logs stop being output after rolling
> > and seem to not recover until the application restarts.
> >
> > We run with a somewhat complicated log configuration, using the
> following:
> > * Async appender
> > * Marker filters
> > * Name filters
> > * Multiple log files
> > * JSON output
> > * cron rollover schedule
> >
> > We use log markers to filter our messages out to their own file. We use a
> > log name filter to filter a statistics class to its own file.
> >
> > We run our application(s) daily and quite constantly, yet, the problem
> > seems to occur anywhere from multiple times a day to spanning a few days
> > between occurrences. When the problem does occur, it seems that it can be
> > corrected upon restarting the application.
> >
> > Here is our log4j2.xml:
> >
> > <?xml version="1.0" encoding="UTF-8"?>
> > <Configuration status="INFO">
> > <Properties>
> > <Property name="cronRolloverSchedule">0 */5 * * * ?</Property>
> > <Property name="logDir">./logs</Property>
> > <Property name="rolloverLogDir">./logs_backup</Property>
> > <Property name="logPattern">%d{ISO8601}{UTC}Z %-5level [%thread] %logger
> -
> > %message%n</Property>
> > <Property name="messagePattern">%d{ISO8601}{UTC}Z %message%n</Property>
> > </Properties>
> > <Appenders>
> > <RollingRandomAccessFile
> > name="Main"
> > fileName="${logDir}/myapp.json.log"
> > filePattern="${rolloverLogDir}/myapp.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> > <JsonLayout
> > properties="true"
> > complete="true" />
> > <Policies>
> > <CronTriggeringPolicy
> > schedule="${cronRolloverSchedule}"
> > evaluateOnStartup="true" />
> > </Policies>
> > </RollingRandomAccessFile>
> > <RollingRandomAccessFile
> > name="Statistics"
> > fileName="${logDir}/myapp.stats.json.log"
> >
> filePattern="${rolloverLogDir}/myapp.stats.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> > <JsonLayout
> > properties="true"
> > complete="true" />
> > <Policies>
> > <CronTriggeringPolicy
> > schedule="${cronRolloverSchedule}"
> > evaluateOnStartup="true" />
> > </Policies>
> > </RollingRandomAccessFile>
> > <RollingRandomAccessFile
> > name="Message"
> > fileName="${logDir}/myapp-messages.json.log"
> >
> filePattern="${rolloverLogDir}/myapp-messages.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> > <JsonLayout
> > properties="true"
> > complete="true" />
> > <Policies>
> > <CronTriggeringPolicy
> > schedule="${cronRolloverSchedule}"
> > evaluateOnStartup="true" />
> > </Policies>
> > </RollingRandomAccessFile>
> > </Appenders>
> > <Loggers>
> > <AsyncRoot level="trace">
> > <AppenderRef ref="Main">
> > <Filters>
> > <MarkerFilter
> > marker="MESSAGE"
> > onMatch="DENY"
> > onMismatch="NEUTRAL" />
> > <MarkerFilter
> > marker="EVENT_STATISTICS"
> > onMatch="DENY"
> > onMismatch="NEUTRAL" />
> > </Filters>
> > </AppenderRef>
> > <AppenderRef ref="Message">
> > <Filters>
> > <MarkerFilter
> > marker="MESSAGE"
> > onMatch="ACCEPT"
> > onMismatch="DENY" />
> > <MarkerFilter
> > marker="EVENT_STATISTICS"
> > onMatch="DENY"
> > onMismatch="NEUTRAL" />
> > </Filters>
> > </AppenderRef>
> > </AsyncRoot>
> > <AsyncLogger
> > name="com.myapp.EventStatistics"
> > level="INFO">
> > <AppenderRef ref="Statistics" />
> > </AsyncLogger>
> > </Loggers>
> > </Configuration>
> >
> > Thanks for the help!
> >
> > - Skye
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: Rolled logs are sometimes empty
Posted by Ralph Goers <ra...@dslextreme.com>.
While I don’t see anything technically wrong with your configuration you could probably simplify it. If all statistics are produced using the com.myapp.EventStatistics logger you can add additivity=“false” to that logger to prevent the events form also being handled by the root logger. I would presume you could then remove the statistics filters.
What OS is this running on and what version of Log4j? I assume you have checked stdout/stderr for any messages that might be printed by Log4j?
Ralph
> On Oct 1, 2018, at 4:32 PM, Skye Antinozzi <an...@morris.umn.edu> wrote:
>
> Hello!
>
> We are using a RollingRandomAccessFile appender with a 5 minute cron
> rollover schedule. On rare occasion logs stop being output after rolling
> and seem to not recover until the application restarts.
>
> We run with a somewhat complicated log configuration, using the following:
> * Async appender
> * Marker filters
> * Name filters
> * Multiple log files
> * JSON output
> * cron rollover schedule
>
> We use log markers to filter our messages out to their own file. We use a
> log name filter to filter a statistics class to its own file.
>
> We run our application(s) daily and quite constantly, yet, the problem
> seems to occur anywhere from multiple times a day to spanning a few days
> between occurrences. When the problem does occur, it seems that it can be
> corrected upon restarting the application.
>
> Here is our log4j2.xml:
>
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="INFO">
> <Properties>
> <Property name="cronRolloverSchedule">0 */5 * * * ?</Property>
> <Property name="logDir">./logs</Property>
> <Property name="rolloverLogDir">./logs_backup</Property>
> <Property name="logPattern">%d{ISO8601}{UTC}Z %-5level [%thread] %logger -
> %message%n</Property>
> <Property name="messagePattern">%d{ISO8601}{UTC}Z %message%n</Property>
> </Properties>
> <Appenders>
> <RollingRandomAccessFile
> name="Main"
> fileName="${logDir}/myapp.json.log"
> filePattern="${rolloverLogDir}/myapp.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> <JsonLayout
> properties="true"
> complete="true" />
> <Policies>
> <CronTriggeringPolicy
> schedule="${cronRolloverSchedule}"
> evaluateOnStartup="true" />
> </Policies>
> </RollingRandomAccessFile>
> <RollingRandomAccessFile
> name="Statistics"
> fileName="${logDir}/myapp.stats.json.log"
> filePattern="${rolloverLogDir}/myapp.stats.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> <JsonLayout
> properties="true"
> complete="true" />
> <Policies>
> <CronTriggeringPolicy
> schedule="${cronRolloverSchedule}"
> evaluateOnStartup="true" />
> </Policies>
> </RollingRandomAccessFile>
> <RollingRandomAccessFile
> name="Message"
> fileName="${logDir}/myapp-messages.json.log"
> filePattern="${rolloverLogDir}/myapp-messages.json.log.%d{yyyy-MM-dd_HHmm}{UTC}Z">
> <JsonLayout
> properties="true"
> complete="true" />
> <Policies>
> <CronTriggeringPolicy
> schedule="${cronRolloverSchedule}"
> evaluateOnStartup="true" />
> </Policies>
> </RollingRandomAccessFile>
> </Appenders>
> <Loggers>
> <AsyncRoot level="trace">
> <AppenderRef ref="Main">
> <Filters>
> <MarkerFilter
> marker="MESSAGE"
> onMatch="DENY"
> onMismatch="NEUTRAL" />
> <MarkerFilter
> marker="EVENT_STATISTICS"
> onMatch="DENY"
> onMismatch="NEUTRAL" />
> </Filters>
> </AppenderRef>
> <AppenderRef ref="Message">
> <Filters>
> <MarkerFilter
> marker="MESSAGE"
> onMatch="ACCEPT"
> onMismatch="DENY" />
> <MarkerFilter
> marker="EVENT_STATISTICS"
> onMatch="DENY"
> onMismatch="NEUTRAL" />
> </Filters>
> </AppenderRef>
> </AsyncRoot>
> <AsyncLogger
> name="com.myapp.EventStatistics"
> level="INFO">
> <AppenderRef ref="Statistics" />
> </AsyncLogger>
> </Loggers>
> </Configuration>
>
> Thanks for the help!
>
> - Skye
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org