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

[Cedric Maion <cedric@maion.com>]

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