Hi Ron, You are right! fd 1 and 2 are blocking log4j from closing the log file properly.
tomcat starts the Java process with: java -Dblah... >> catalina.out 2>&1 & I wonder how we did not notice this in the past years. Thanks again Simon On Thu, Mar 31, 2016 at 2:38 PM, Ron Gonzalez <[email protected]> wrote: > My first inclination is that you shouldn't have two locks on the same file > from the same process. That points to multiple writers independently > locking the file. This means when one tries to roll the other will still > retain the lock on the file blocking the other one. > > You should identify whether your application code has a handle leak or > whether different components are instantiating multiple versions of log4j > which both want to retain locks to the same file. > > A thread dump from the jvm when the issue is happening should help isolate > it. > > HTH > > Ron > On Mar 31, 2016 4:14 PM, "Simon Chan" <[email protected]> wrote: > > > 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 > > >
