in_tail: throws and exception on logrotation

[giner]

Problem
If td-agent is not running as root and in_tail plugin is in use then it throws and exception on log rotation (if create option is in use) from time to time.

2016-04-15 13:00:32 +0000 [error]: Permission denied - /var/log/nginx/nginx.log
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:364:in `initialize'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:364:in `open'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:364:in `on_notify'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:151:in `on_notify'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:258:in `call'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:258:in `on_change'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.1/lib/cool.io/loop.rb:96:in `run_once'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.1/lib/cool.io/loop.rb:96:in `run'
  2016-04-15 13:00:32 +0000 [error]: /usr/lib/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.38/lib/fluent/plugin/in_tail.rb:81:in `run'

This happens if "create" for logrotate is in use. In this case logrotate creates a new file with restricted permissions first and then changes permissions and ownership to the requested ones. If td-agent tries to read the file in between it throws an error.

Behavior of logrotate

cat > /tmp/logrotate-test << 'EOF'
/tmp/test/*.log {
  rotate 48
  daily
  missingok
  compress
  delaycompress
  create 0644 www-data root
}
EOF

mkdir /tmp/test
touch /tmp/test/test.log

sudo chown root:root /tmp/logrotate-test /tmp/test
sudo chmod 400 /tmp/logrotate-test
sudo strace -fs 1000 -o /tmp/strace.logrotate.log logrotate --force --state /tmp/logrotate.state /tmp/logrotate-test

$ grep -A4 'open("/tmp/test/test.log"' /tmp/strace.logrotate.log 
22035 open("/tmp/test/test.log", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 3
22035 fchmod(3, 0600)                   = 0
22035 fchown(3, 33, 0)                  = 0
22035 fchmod(3, 0644)                   = 0
22035 close(3)                          = 0

[repeatedly]

If td-agent tries to read the file in between it throws an error.

Is this resolved after permission changed?

[giner]

Yes, it does not seem to cause any issues apart of this message in td-agent log.

[repeatedly]

If so, it seems no problem.
Do you want to ignore this permission error logs?
From fluentd side, hard to judge persmission change is expected or not.

[giner]

We tail td-agent logs by rsyslog with filtering to catch misbehaving (what happens sometimes) and the only problem is that this message is misleading. What if td-agent does one more try in a second and if no success then throws an error?

[repeatedly]

What if td-agent does one more try in a second and if no success then throws an error?

It seems good for me.

[ashie]

Fixed by #3378 and #3478
It outputs only warning message on every retry and suppress stack trace.