Rails 3.2.2 logs are not locked for writing between processes #5388

Closed
thoughtafter opened this Issue Mar 12, 2012 · 10 comments

Projects

None yet

5 participants

@thoughtafter

I have a small app that I recently upgraded to Rails 3.2.2. I've noticed my production logs now have entries that are overlapping indicating that the log file is not being locked for writes between processes (I'm using unicorn with 4 processes). Entries look like this:

Started GET "/search?q=blip" for 0.0.0.0 at 2012-03-12 02:20:18 -0700
Processing by SiteController#search as /
Parameters: {"q"=>"blip"}

Started GET "/search?q=2bxen" for 0.0.0.0 at 2012-03-12 02:20:20 -0700
Processing by SiteController#search as /
Parameters: {"q"=>"2bxen"}
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb within layouts/foo (1279.3ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb (0.6ms)
Rendered site/foo.html.erb (0.0ms)
Completed 200 OK in 2600ms (Views: 726.5ms | ActiveRecord: 556.8ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.erb within layouts/foo (366.4ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb (0.5ms)
Rendered site/foo.html.erb (0.0ms)
Completed 200 OK in 550ms (Views: 326.6ms | ActiveRecord: 43.3ms)

My apologies if this is not a Rails bug or if it is some sort of configuration issue. This did not occur until the upgrade to 3.2.2.

@tenderlove
Member

I think we should be logging the pid in production logs. I'll change the formatter for production.

@tenderlove tenderlove added a commit that closed this issue Mar 12, 2012
@tenderlove tenderlove allow people to specify custom formatters, use the default formatter …
…in production so that PID and timestamp are logged. fixes #5388
51aeae9
@cgriego
Contributor
cgriego commented Mar 13, 2012

We've actually seen corruption of the log file from this issue, where lines of log output are interrupted by other lines of log output. No log format can help that.

@thoughtafter

While I like the addition of pids to the log file I don't think it addresses the underlying problem. Most likely 3.2.2 will break any existing log parser. Now that I've had some time to think about it, the best solution appears to be to not write to the log during the request but only the complete entry after the response is sent. So this bug is poorly titled because adding locking to the logfile seems like it would be problematic. Add the pid to every line could work but any existing parser would have to be rewritten.

@tenderlove
Member

@thoughtafter waiting until the request is finished will not fix this. Two requests could finish at exactly the same time. Also, writing out logs during the request helps with debugging (in case you have slow queries, service requests such as CC processors, etc). Also, my commit is only in master (just for Rails 4.0), and you can set the formatter back to the original via the config file, so we should be able to maintain backwards compatibility. :-)

@cgriego Nope. We can try to reduce the size of the logs lines to PIPE_BUF, which should allow each write to be atomic. But we can't control all output sizes (like exceptions and stuff). If you want to avoid mangled logs and increase performance, I highly recommend you switch to using something like SyslogLogger.

@thoughtafter

Can you explain why the problem of overlapping log entries began with 3.2.2? Is it due to changing sync to true? If so, will changing that setting revert to the previous behavior?

@tenderlove
Member

The possibility of overlapping logs exists in any version of rails where multiple processes write to the same file. Buffering logs before writing them to the file can reduce the possibility, but it's still a problem.

POSIX says that writes smaller than PIPE_BUF are guaranteed to be atomic and that:

Writes of greater than {PIPE_BUF} bytes may have data interleaved, on arbitrary boundaries, with writes by other processes, whether or not the O_NONBLOCK flag of the file status flags is set.

As I said, we could try reducing each log message to less than the size of PIPE_BUF, but it is OS specific. :(

Hope that helps!

@Fjan
Contributor
Fjan commented Jun 7, 2012

@tenderlove can you explain why switching to SyslogLogger would not suffer from the same request interleaving problem as the standard Logger in this case?

Given that PIPE_BUF is 4K on Linux it seems that the suggestion by @cgriego would work: switch off sync on the log file and call flush on the file after every request. That should result in atomic writes of each request no?

@Fjan
Contributor
Fjan commented Jun 7, 2012

In case anybody else runs into this problem, here's a tiny monkey patch that implements this. Note that you need to switch off sync on the underlying log file in your production.rb and it won't work if a single request outputs more than 4K.

module ActiveSupport
  class BufferedLogger
    def flush
      @log_dest.flush
    end
    def respond_to?(method, include_private = false)
      super
    end
  end
end
@sawtelle
sawtelle commented Jul 7, 2012

For those wishing to use Fjan's patch above, this shows how one can "switch off sync":

Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = false

As of 3.2.6 (and possibly earlier) the existing Rails middleware does flush after the request, so something like this and Fjan's patch are all you need in order to have multiple workers write to the same production.log without tossing the lines into an incomprehensible salad.

Where's the best place to discuss making a change to Rails so that without monkey-patching the default logger can be configured to serve effectively in production?

@Fjan
Contributor
Fjan commented Jul 7, 2012

Thanks for clarifying that. That's actually more elegant than what I did (I opened a new file without the sync and set config.logger=ActiveSupport::BufferedLogger.new(f))

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment