1

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>
4
  • 1
    It might be that the %04i prevents rollover. Try to add inside <RollingFile> the entry <DefaultRolloverStrategy max="200"/>. If it helps, choose a big maximum. See Appenders for examples of using DefaultRolloverStrategy max.
    – harrymc
    Mar 8 at 17:34
  • Harry, I've been reading and re-reading the doc you linked for a long time. And I of little faith had little confidence in your advice but was game to try it anyway, as anything else would have been rude. Whaddaya know, YOU WERE RIGHT! I'm up to cycle 121 as I write. Strange, and I would much prefer my log files to have sortable names, but at least they won't be munged by artificial limits any more. Thank you for your suggestions! I'm not sure if it's the %i or the explicit (rather than default, according to doc) max cycle, but now I have a direction in which to experiment. Mar 8 at 18:32
  • I added an answer, until you find more in your tests. Feel free to edit my answer if you wish.
    – harrymc
    Mar 8 at 18:43
  • I've gotten around the "sortable file names" problem by starting the backup index at 10000 . I don't anticipate more than 90,000 log files in one day! Mar 9 at 9:39

2 Answers 2

2

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.

0
0

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

2
  • It seems that my idea was correct, as funny as it seems. This merits your publishing a bug report, or at least asking for a clarification of the documentation.
    – harrymc
    Mar 9 at 9:23
  • Done. Thanks again for your help! Mar 9 at 9:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.