Why does log4j limit backup cycles?

Question

I have a java app that uses log4j for logging. Everything was good until the log4Shell scare and I was forced to upgrade to 2.17.1 .

My app uses startup, time and size based rollover strategies. Normally it will produce about 6 log files per day. But some days when things go really crazy (and I need those log files the most), the number of files may exceed 100 in a day. Program keeps crashing, a watchdog keeps waking it up.

The version that ran before, with nothing changed but log4j version, started overwriting the last log file after a fixed number, probably 100. I started using %04i in the file name so I got good readable cycle numbers. My current config doesn't trash the last file any more, but this happens:

-rw-r--r-- 1 xxxxxxx xx    588 Mar  8 17:08 TRACE.2022-03-08-17.0096.log
-rw-r--r-- 1 xxxxxxx xx    213 Mar  8 17:08 TRACE.2022-03-08-17.0097.log
-rw-r--r-- 1 xxxxxxx xx    588 Mar  8 17:09 TRACE.2022-03-08-17.0098.log
-rw-r--r-- 1 xxxxxxx xx    213 Mar  8 17:09 TRACE.2022-03-08-17.0099.log
-rw-r--r-- 1 xxxxxxx xx  65619 Mar  8 17:26 TRACE.2022-03-08-17.0100.log

At 100, log4j simply stops cycling.

The docs don't mention any such limit. What gives?

Below is my latest configuration. The app is a minimal example, rolls the file at just 500 bytes and is intended to restart cycles on hour boundaries rather than days, but the principles should still apply.

The config, also, is one sample of many variations on combinations of trigger and rollover strategy, filename pattern and appender. Everything I've tried has run into this limit.

I can think of some workarounds but I'd prefer to understand the cause of the problem better. I'd appreciate any insight or advice I can get.

  1 <?xml version="1.0" encoding="UTF-8"?>
  2 <Configuration status="WARN">
  3     <Appenders>
  4         <RollingFile name="TRACE"
  5                 filePattern="./trace/TRACE.%d{YYYY-MM-dd-HH}.%04i.log">
  6                 <!-- ex-fileName=   "./trace/TRACE.log" -->
  7             <Policies>
  8                 <OnStartupTriggeringPolicy />
  9                 <SizeBasedTriggeringPolicy size="500 B" />
 10                 <TimeBasedTriggeringPolicy />
 11                 <!-- CronTriggeringPolicy schedule="0 0 * * * ?" / -->
 12             </Policies>
 13             <DirectWriteRolloverStrategy />
 14             <PatternLayout>
 15                 <header>%d{ISO8601} ---------- Trace file started. ----------\n</header>
 16                 <footer>%d{ISO8601} ----------- Trace file ended. -----------\n</footer>
 17                 <Pattern>%d{ISO8601} [%-4.-4t %-15.-15M#%4L] %-5level %msg%n%xEx{full}</Pattern>
 18             </PatternLayout>  "/>
 19         </RollingFile>
 20     </Appenders>
 21     <Loggers>
 22         <Root level="error">
 23             <AppenderRef ref="TRACE"/>
 24         </Root>
 25         <Logger name="minimal" level="trace" additivity="false">
 26             <AppenderRef ref="TRACE"/>
 27         </Logger>
 28     </Loggers>
 29 </Configuration>

Answer 1

My idea that the %04i prevents rollover seems to have something in it.

Adding inside the <RollingFile> tag the entry

<DefaultRolloverStrategy max="200"/>

has helped bypass the 100 limit.

You may as a workaround choose a big maximum limit, with some cleanup method.

According to the documentation at Appenders, there also exists also a nomax argument which might also help.

Answer 2

With some helpful hints from @harrymc and a number of experiments, I now believe I'm looking at a bug in log4j, or at least a case of inadequate documentation. Here are the results of my tests, each with some variation on parameters to RollingFileAppender.filePattern and xxxRolloverStrategy:

• if filePattern contains %06i, cycling breaks after 100.
• if filePattern contains %006i, it breaks after 100 also.
• if filePattern contains %6i, it breaks after 10.
• if filePattern contains %06i and DefaultRolloverStrategy.min=10000, max=99999, it breaks after just 1.
• setting DefaultRolloverPattern.fileIndex to nomax doesn't change the above.
• file cycling works OK if filePattern contains %i.

Now it's true that the log4j documentation mentions only "%i" as a format specifier for the numeric cycle index, so I guess it's technically not a bug. I find it problematic, though, that specifying a field width and leading zeroes as for C's printf or Javas String.format()` functions seems to work as expected until you get to unusually large cycle numbers (in excess of 100).

log4j's documentation for RollingRandomAccessFileAppender does explicitly recommend modifiers for the index format spec:

... and/or a %i which represents an integer counter. The integer counter allows specifying a padding, like %3i for space-padding the counter to 3 digits or (usually more useful) %03i for zero-padding the counter to 3 digits.

This leads me to question why the handling of the index parameter is different for these two otherwise very similar appenders.

UPDATE: I've filed a bug report: https://issues.apache.org/jira/browse/LOG4J2-3432