Log reopening broken on Rails 4 with config.autoflush_log = false?

Log reopening broken on Rails 4 with config.autoflush_log = false?

[Cedric Maion]

Hi there,

On a Rails 4.0 app with 'config.autoflush_log = false', it seems to me
that telling unicorn to reopen log files fails (e.g., after a log
rotation and USR1 signal, Rails/unicorn still writes to the old rotated
file instead of reopening a new one).

Without this config option, logs does properly get reopened.


Is this something known?


Example:

=> First, with config.autoflush_log set to false:

$ grep autoflush config/environments/production.rb
  config.autoflush_log = false
$ script/unicorn upgrade
....
$ ps -ef | grep unicorn
10001    27332     1 79 16:28 ?        00:00:45 unicorn master -D -c /path/to/app/current/config/unicorn.rb -E production
10001    27813 27332  9 16:29 ?        00:00:00 unicorn worker[0] -D -c /path/to/app/current/config/unicorn.rb -E production
[...]
$ lsof -p 27332 | grep log
ruby    27332 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    27332 app-user    2w   REG      251,0     2784 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    27332 app-user    7w   REG      251,0    76835 7110394 /path/to/app/shared/log/production.log
$ mv /path/to/app/shared/log/production.log /path/to/app/shared/log/production.log.old
$ lsof -p 27332 | grep log
ruby    27332 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    27332 app-user    2w   REG      251,0     2784 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    27332 app-user    7w   REG      251,0    76835 7110394 /path/to/app/shared/log/production.log.old
$ kill -USR1 27332
$ lsof -p 27332 | grep log
ruby    27332 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    27332 app-user    2w   REG      251,0     3092 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    27332 app-user    7w   REG      251,0    76835 7110394 /path/to/app/shared/log/production.log.old

=> still writing on the old production.log.old file


=> Now, without config.autoflush_log:

$ grep autoflush config/environments/production.rb
  #config.autoflush_log = false
$ script/unicorn upgrade
....
$ ps -ef | grep unicorn
10001    28621     1 85 16:31 ?        00:00:45 unicorn master -D -c /path/to/app/current/config/unicorn.rb -E production
10001    29100 28621 18 16:31 ?        00:00:00 unicorn worker[0] -D -c /path/to/app/current/config/unicorn.rb -E production
[...]
$ lsof -p 28621 | grep log
ruby    28621 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    28621 app-user    2w   REG      251,0     3867 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    28621 app-user    7w   REG      251,0     1914 7105763 /path/to/app/shared/log/production.log
$ mv /path/to/app/shared/log/production.log /path/to/app/shared/log/production.log.old
$ lsof -p 28621 | grep log
ruby    28621 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    28621 app-user    2w   REG      251,0     4175 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    28621 app-user    7w   REG      251,0     1746 7110394 /path/to/app/shared/log/production.log.old
$ kill -USR1 28621
$ lsof -p 28621 | grep log
ruby    28621 app-user    1w   REG      251,0        0 7106215 /path/to/app/shared/log/unicorn.stdout.log
ruby    28621 app-user    2w   REG      251,0     4483 7105641 /path/to/app/shared/log/unicorn.stderr.log
ruby    28621 app-user    7w   REG      251,0        0 7105763 /path/to/app/shared/log/production.log

=> now writing on newly reopened log


Thanks,

    Cedric

Re: Log reopening broken on Rails 4 with config.autoflush_log = false?

[Eric Wong]

Cedric Maion <cedric@maion.com> wrote:
> On a Rails 4.0 app with 'config.autoflush_log = false', it seems to me
> that telling unicorn to reopen log files fails (e.g., after a log
> rotation and USR1 signal, Rails/unicorn still writes to the old rotated
> file instead of reopening a new one).
> 
> Without this config option, logs does properly get reopened.
> 
> Is this something known?

Yes, log buffering via File#sync=true is incompatible with reopening in
multiprocess servers.  File#sync=true does not guarantee writes are
atomic on line boundaries, so it's dangerous to assume they're logs.

Even without reopening, enabling this option on a multiprocess server
might corrupt logs (depending on the buffering implementation)
because the synchronization is within each process rather for the
entire OS.

Looking at the rails source:
==> railties/lib/rails/application/bootstrap.rb <==
          f = File.open path, 'a'
          f.binmode
          f.sync = config.autoflush_log # if true make sure every write flushes

You're not likely to notice any performance difference unless you're
logging excessively.  Keep in mind the Linux kernel also does buffering
and you can tune that via the sys.vm.dirty_* sysctls.

[PATCH] FAQ: add entry for Rails autoflush_log

[Eric Wong]

Thanks to Cedric Maion for bringing this up on the mailing list:
http://bogomips.org/unicorn-public/m/20140703144048.GA6674@cedric-maion.com
---
 This updates http://unicorn.bogomips.org/FAQ.html

 FAQ | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/FAQ b/FAQ
index c84a8af..66f1a09 100644
--- a/FAQ
+++ b/FAQ
@@ -1,6 +1,14 @@
 = Frequently Asked Questions about Unicorn
 
-===  I've installed Rack 1.1.x, why can't Unicorn load Rails (2.3.5)?
+=== Why aren't my Rails log files rotated when I use SIGUSR1?
+
+The Rails autoflush_log option must remain disabled with multiprocess
+servers such as unicorn.  Buffering in userspace may cause lines to be
+partially written and lead to corruption in the presence of multiple
+processes.  With reasonable amounts of logging, the performance impact
+of autoflush_log should be negligible on Linux and other modern kernels.
+
+=== I've installed Rack 1.1.x, why can't Unicorn load Rails (2.3.5)?
 
 Rails 2.3.5 is not compatible with Rack 1.1.x.  Unicorn is compatible
 with both Rack 1.1.x and Rack 1.0.x, and RubyGems will load the latest
-- 
EW

Re: Log reopening broken on Rails 4 with config.autoflush_log = false?

[Cedric Maion]

Hi Eric,

Thanks for your answer (and update to the FAQ ;) ).

I'm playing with autoflush_log = true and see if I find a performance
impact (I'm logging approx 20KB per sec).

sys.vm.dirty* sysctls are already changed, but with low ratios as those
systems are also writing large files (and I don't want those pages in
memory for too long).

If a performance impact can be measured, I believe that I will turn
autoflush_log to false again and modify Unicorn::Util#is_log? to accept
!fp.sync ;) (I'm willing to accept occasional log lines corruption esp
during rotation)... or just restart unicorn after rotation instead.

Or, thinking out loud... keep autoflush_log to false and have unicorn
flush logs itself regularly, outside the HTTP request path (and when
reopening logs), to avoid blocking on IO during a log flush in the
middle of a request? (I need to refresh myself on the sizes of the ruby
& system IO buffers though, not sure if it's worth the pain).

    Cedric

On Thu, Jul 03, 2014 at 05:24:10PM +0000, Eric Wong wrote:
>
> Cedric Maion <cedric@maion.com> wrote:
> > On a Rails 4.0 app with 'config.autoflush_log = false', it seems to me
> > that telling unicorn to reopen log files fails (e.g., after a log
> > rotation and USR1 signal, Rails/unicorn still writes to the old rotated
> > file instead of reopening a new one).
> >
> > Without this config option, logs does properly get reopened.
> >
> > Is this something known?
>
> Yes, log buffering via File#sync=true is incompatible with reopening in
> multiprocess servers.  File#sync=true does not guarantee writes are
> atomic on line boundaries, so it's dangerous to assume they're logs.
>
> Even without reopening, enabling this option on a multiprocess server
> might corrupt logs (depending on the buffering implementation)
> because the synchronization is within each process rather for the
> entire OS.
>
> Looking at the rails source:
> ==> railties/lib/rails/application/bootstrap.rb <==
>           f = File.open path, 'a'
>           f.binmode
>           f.sync = config.autoflush_log # if true make sure every write flushes
>
> You're not likely to notice any performance difference unless you're
> logging excessively.  Keep in mind the Linux kernel also does buffering
> and you can tune that via the sys.vm.dirty_* sysctls.