fluentd: in_tail fails to detect file rotation with log4 logs

I’m seeing this behavior with log files created with log4j. Rotation is detected sometimes 20-30 minutes after the actual file rotation. Rotation happens every hour.

Running fluentd 0.12.4 installed from gem with ruby 2.1

From fluent.log:

2015-01-28 14:34:25 +0200 [info]: detected rotation of /var/log/server/server.log; waiting 5 seconds 2015-01-28 14:34:25 +0200 [info]: following tail of /var/log/server/server.log 2015-01-28 15:42:36 +0200 [info]: detected rotation of /var/log/server/server.log; waiting 5 seconds 2015-01-28 15:42:36 +0200 [info]: following tail of /var/log/server/server.log 2015-01-28 17:09:30 +0200 [info]: detected rotation of /var/log/server/server.log; waiting 5 seconds 2015-01-28 17:09:30 +0200 [info]: following tail of /var/log/server/server.log

lsof

lsof shows fluent holding all the rotated file handlers. The previous file (/var/log/server/server.log.2015-01-28-17) is held twice: $ lsof -n | grep server/server.log fluentd 4725 fluentd 31u REG 9,0 6989675986 3145756 /var/log/server/server.log.2015-01-28-17 fluentd 4725 fluentd 32r REG 9,0 6989675986 3145756 /var/log/server/server.log.2015-01-28-17 fluentd 4725 fluentd 38r REG 9,0 5032834348 3145970 /var/log/server/server.log.2015-01-28-08 fluentd 4725 fluentd 40r REG 9,0 4424197667 3146026 /var/log/server/server.log.2015-01-28-12 fluentd 4725 fluentd 41r REG 9,0 4548295792 3145977 /var/log/server/server.log.2015-01-28-09 fluentd 4725 fluentd 42r REG 9,0 4386869199 3145992 /var/log/server/server.log.2015-01-28-10 fluentd 4725 fluentd 44r REG 9,0 4326276642 3146012 /var/log/server/server.log.2015-01-28-11 fluentd 4725 fluentd 45r REG 9,0 5918476136 3146068 /var/log/server/server.log.2015-01-28-15 fluentd 4725 fluentd 46r REG 9,0 4520370894 3146040 /var/log/server/server.log.2015-01-28-13 fluentd 4725 fluentd 47r REG 9,0 4748760626 3146054 /var/log/server/server.log.2015-01-28-14 java 4968 tomcat6 42u REG 9,0 2526929547 3145760 /var/log/server/server.log

Source configuration

<source>
  type tail
  format multiline
  # Match the date at the beginning of each entry, which can be in one of two
  # different formats.
  format_firstline /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{1,3}) \[(?<thread>[^ ]*)\]/
  format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{1,3}) \[(?<thread>[^ ]*)\] \[(?<user>[^ ]*[ ]?)\] (?<level>[^\s]+)(?<message>.*)/
  path /var/log/server/server.log
  pos_file /var/tmp/fluentd.server.pos
  read_from_head true
  tag server
</source>

About this issue

Original URL
State: closed
Created 9 years ago
Comments: 15 (9 by maintainers)

Most upvoted comments

I close this issue because this is DailyRollingFileAppender problem and handing in in_tail is toooooo hard. If someone hits similar problem with thread-safety appender, please re-open this issue.

repeatedly on Feb 13, 2015

Download log4j 1.2.17 from http://central.maven.org/maven2/log4j/log4j/1.2.17/log4j-1.2.17.jar Compile like so:

$ javac -cp ./:log4j-1.2.17.jar Issue554.java

To run:

java -cp ./:log4j-1.2.17.jar Issue554 <threads> <log interval>

I was able to recreate the problem when using 30 threads at 10ms interval. Running on EC2, 8 cores, 15G of RAM.

java -cp ./:log4j-1.2.17.jar Issue554 30 10

Issue554.java:

import java.io.IOException;
import org.apache.log4j.Logger;

class MyRunnable implements Runnable {
    private Logger logger=null;
    private int sleepInterval;

    public MyRunnable(int sleepInterval) {
        logger = Logger.getLogger(Issue554.class.getName());
        this.sleepInterval = sleepInterval;
    }

    public void run() {
        while (true) {
                for(int i=0;i<30;i++) {
                    logger.warn("The quick brown fox jumps over the lazy dog The quick brown fox jumps over the lazy dog");
                }
            try {
                Thread.sleep(this.sleepInterval);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}


public class Issue554 {

    public static void main(String[] args) throws IOException {
        int threads = Integer.parseInt(args[0]);
        int sleepInterval = Integer.parseInt(args[1]);
        System.out.println("Logging from " + Integer.toString(threads) + " threads, in intervals of " + Integer.toString(sleepInterval) + "ms");

        Thread[] worker=new Thread[threads];
        MyRunnable r = new MyRunnable(sleepInterval);

        for(int i=0;i<threads;i++) {
            worker[i]=new Thread(r);
            worker[i].start();
        }
    }
}

fluentd.conf

<source>
  type tail
  format multiline
  format_firstline /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{1,3}) \[(?<thread>[^ ]*)\]/
  format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{1,3}) \[(?<thread>[^ ]*)\] \[(?<user>[^ ]*[ ]?)\] (?<level>[^\s]+)(?<message>.*)/
  #format2 /(?<message>.*)/
  path ./server.log
  pos_file /tmp/fluentd.server.pos
  read_from_head true
  tag server
</source>

<match **>
    type null
</match>

log4j.properties

log4j.rootLogger=WARN, R

log4j.appender.R=org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.File=./server.log
log4j.appender.R.DatePattern='.'yyyy-MM-dd-HH-mm
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d [%t] [%x] %-5p %c - %m%n

katriel on Feb 2, 2015