Behavior changes in log4j 2.x

Concurrent file access

In log4j 2.x, the behavior of concurrent file access by multiple processes is different from the behavior in log4j 1.x. The difference is in the RollingFileAppender, which IBM® Content Manager V8.7 (and later versions) uses by default.

IBM Content Manager V8.6 using log4j 1.x

If two processes wrote to the same file using a RollingFileAppender, and the file got big enough to rollover, log4j recognized that another process had locked the file; it would not rollover while the other process accessed the file. The result was that the rollover settings were ignored, and the file continued to get bigger.

IBM Content Manager V8.7 using log4j 2.x

log4j 2 produces an error when trying to rollover to a new file. The error looks something like this:
2022-03-29 03:11:12,078 main ERROR Unable to delete file
C:\IBM\db2cmv8\log\connectors\Administrator.dklog.log: java.nio.file.FileSystemException
C:\IBM\db2cmv8\log\connectors\Administrator.dklog.log: The process cannot access the file because it is being used by another process.

When this error occurs, the old log file is given a new name, and the existing one is overwritten. However, if there is a lot of concurrent access, two processes might try to rollover at the same time, which might cause inconsistencies in the trace files.

This might happen if:

  • the IBM Content Manager system administration client and your application run on the same system, and they use the same operating system user ID, or
  • two application processes are running. Usually, this is not an problem when running at the ERROR level of trace (which is the default level), because most applications have few errors, so the trace files are unlikely to rollover. However, when troubleshooting, a lot of information is written to the trace files, so this might be a problem.

If your environment requires concurrent access when troubleshooting information is being collected, consider one of the following solutions:

  • Run different applications under different operating system user IDs.

    log4j uses the user name in the trace file name, so if each application runs under a different user ID, they write to different trace files and never conflict. This is the preferred solution, because it can be used for both steady state and troubleshooting, without changing the trace settings.

  • Add the process ID of the application to the file name.

    To do this, set the DKAPIJavaLogAddProcessIdToFileName option in the cmblogconfig.properties file to ON. However, this solution adds overhead to the trace configuration, so running different applications under different user IDs is preferred.

  • Use a bigger file so that rollover will not happen.

    During troubleshooting, you usually want to save all trace entries. Make the file big enough to hold all entries, so that you avoid the problem.

  • Use the FileAppender with the locking option set to ‘true’.

    The FileAppender writes to one file that grows indefinitely; however, it supports locking for concurrent access (the RollingFileAppender does not). This might be useful when troubleshooting, because it means that all trace entries are saved. However, you must regularly delete the trace file, or delete entries from it, so that it does not occupy excess space. This is usually not a problem when troubleshooting, but might be if it used for a long time.

  • Use DirectWriteRolloverStrategy instead of DefaultRolloverStrategy.

    This strategy does not eliminate the problem, but it might mitigate it. Using this strategy, errors do not occur on the first rollover, but they still occur when rolling over on the configured maximum number of files, if one process has locked the first file. Using this strategy with bigger files and more files might eliminate the problem in some cases.

  • Use separate log4j2.xml files for each application, and make sure that each application writes its trace files to a different directory.

    Each application has its own deployment, so it can have its own log4j2.xml file.