Mailing-List: contact log4j-user-help@logging.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Log4J Users List" <log4j-user@logging.apache.org>
MIME-Version: 1.0
Date: Thu, 31 Mar 2016 13:14:49 -0700
Message-ID: 
 <CAHO7rretu9eJBcngGzV5s0DsZB0sYKvWgcOGqpcYDUzW61b9fA@mail.gmail.com>
Subject: rolled log file continues to grow unbound
From: Simon Chan <sialnije@gmail.com>
To: log4j-user@logging.apache.org
Content-Type: multipart/alternative; boundary=001a1135199a1d2260052f5dea5f

--001a1135199a1d2260052f5dea5f
Content-Type: text/plain; charset=UTF-8

Greetings,

Hope someone has heard of the problem below or can suggest workarounds or
how to debug this thing.

Problem:
=======
- After rolling, the old (rotated) log file continues to pick up entries
and grows.
  The new log file picks up WARN and INFO level logs. The old/rolled file
picks
  up ERROR level logs.
- After max rotations, the filename no longer visible to "ls". But the Java
process
  still has 2 file descriptors pointing at the deleted file. The file will
keep
  growing until it eats up all disk space.
- Only a handful systems have this problem. We have about 20 systems
  in the lab and most of them rotate correctly.
  One system has this bug happening 100% of the time, meaning after
restarting the
  Java process, the rotation problem appears at the first rollover.
  It is our stress test system and generates quit a bit of log entries
(busy but not
  ridiculously busy).
- 3 other systems entered the above state after moderate effort to
  filled the log file to trigger rolling.

Other Symtoms:
=============
Output from the command "ls -l /proc/<pid>/fd | grep catalina.out":
Mar 31 11:21 1 -> /var/log/tomcat/catalina.out.1
Mar 31 11:21 111 -> /var/log/tomcat/catalina.out
Mar 31 11:21 2 -> /var/log/tomcat/catalina.out.1

We have another Java process using identical log4j properties file
(except the log filename part). This process has no rotation problem.
"lsof | grep log4j" output shows this other process has handles
to log4j-1.2.15.jar. But the tomcat process which has rotation
problem does not?! Not sure if this means anything.


History and Environment:
=======================
We have been using log4j since 2012 without any issues. There are about 200
customers using this configuration:

- CentOS 6.4, 6.5 and 6.6 (systems upgrade to latest CentOS releases)
- Java 6 (openjdk)
- tomcat 6.0.32
- log4j 2.15 (base on the filename log4j-1.2.15.jar)
- Dell server with 16G RAM and 12 CPU cores (2 sockets X 6 cores)

This problem appears recently when we upgrade our system to the followings:
- CentOS 6.7
- Java 8 (currently java-1.8.0-openjdk-1.8.0.77-0.b03)
- tomcat 6.0.45 (at one point the stress test system used 6.0.32 and
already
  exhibited the rotation problem)
- log4j 2.15

log4j.properties:
================
log4j.rootLogger=WARN, R

##rolling appender
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=${catalina.home}/logs/catalina.out
log4j.appender.R.MaxFileSize=10MB
log4j.appender.R.MaxBackupIndex=10
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

## logging levels
log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost]=WARN
log4j.logger.org.apache.catalina.core=WARN
log4j.logger.org.apache.catalina.session=WARN
log4j.logger.com.ourcompany=INFO

tomcat config
==========
Probably relevant but there are multiple conf files and web.xml and I don't
know which involve logging.

Regards,
Simon

--001a1135199a1d2260052f5dea5f--