Rails 3.2.2 log files unordered, requests intertwined

Question

I recollect getting log files that were nicely ordered, so that you could follow one request, then the next, and so on.

Now, the log files are, as my 4 year old says "all scroggled up", meaning that they are no longer separate, distinct chunks of text. Loggings from two requests get intertwined/mixed up.

For instance:

Started GET /foobar
...
Completed 200 OK in 2ms (Views: 0.4ms | ActiveRecord: 0.8ms)
Patient Load (wait, that's from another request that has nothing to do with foobar!)
[ blank space ]
Something else

This is maddening, because I can't tell what's happening within one single request.

This is running on Passenger.

I think is related http://news.ycombinator.com/item?id=4483390 — fguillen, Jan 10 '13 at 16:23

score 4 · Answer 1 · answered Aug 29 '12 at 20:48

I tried to search for the same answer but couldn't find any good info. I'm not sure if you should fix server or rails code.

If you want more info about the issue here is the commit that removed old way of logging https://github.com/rails/rails/commit/04ef93dae6d9cec616973c1110a33894ad4ba6ed

score 4 · Answer 2 · answered Sep 06 '12 at 10:14

4

If you value production log readability over everything else you can use the

PassengerMaxInstancesPerApp 1

configuration. It might cause some scaling issues. Alternatively you could stuff something like this in application.rb:

process_log_filename = Rails.root + "log/#{Rails.env}-#{Process.pid}.log"
log_file = File.open(process_log_filename, 'a')
Rails.logger = ActiveSupport::BufferedLogger.new(log_file)

answered Sep 06 '12 at 10:14

Manfred Stienstra

356
2
5

2

If I'm not mistaken, if you happened to get a PID of a previous process, that would overwrite your older log file. This could be mitigated to some degree by frequent rotation, but since PID's are not something you can count on, that still is not 100% safe. I think you'd want to add a timestamp or something to the log file name. Also: the PassengerMaxInstancesPerApp suggestion is pretty useless, bordering on snarky; I'd remove it from your answer. – David N. Welton Sep 06 '12 at 11:12
6

I downvoted this answer, because you should never have suggested that PassengerMaxInstancesPerApp change. It's akin to suggesting a line of code that deletes your root directory if someone asks how to free up hard disk space. Please revise. – trisweb Sep 06 '12 at 13:17
The PassengerMaxInstancesPerApp is partly a joke, but also a real solution if you're using it during development. – Manfred Stienstra Oct 24 '12 at 10:23

score 3 · Accepted Answer · edited May 23 '17 at 12:06

Yep!, they have made some changes in the ActiveSupport::BufferedLogger so it is not any more waiting until the request has ended to flush the logs:

But they have added the ActiveSupport::TaggedLogging which is very funny and you can stamp every log with any kind of mark you want.

In your case could be good to stamp the logs with the request UUID like this:

# config/application.rb
config.log_tags = [:uuid]

Then even if the logs are messed up you still can follow which of them correspond to the request you are following up.

You can make more funny things with this feature to help you in your logs study:

score 3 · Answer 4 · answered Feb 01 '13 at 12:10

Well, for me the TaggedLogging solution is a no go, I can live with some logs getting lost if the server crashes badly, but I want my logs to be perfectly ordered. So, following advice from the issue comments I'm applying this to my app:

# lib/sequential_logs.rb
module ActiveSupport
  class BufferedLogger
    def flush
      @log_dest.flush
    end
    def respond_to?(method, include_private = false)
      super
    end
  end
end

# config/initializers/sequential_logs.rb
require 'sequential_logs.rb'

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

As far as I can say this hasn't affected my app, it is still running and now my logs make sense again.

score 0 · Answer 5 · answered Sep 06 '12 at 10:49

0

They should add some quasi-random reqid and write it in every line regarding one single request. This way you won't get confused.

answered Sep 06 '12 at 10:49

alamar

18,729
4
64
97

score 0 · Answer 6 · answered May 29 '14 at 21:03

0

I haven't used it, but I believe Lumberjack's unit_of_work method may be what you're looking for. You call:

Lumberjack.unit_of_work do
  yield
end

And all logging done either in that block or in the yielded block are tagged with a unique ID.

answered May 29 '14 at 21:03

JacobEvelyn

3,901
1
40
51

Rails 3.2.2 log files unordered, requests intertwined

6 Answers6

Linked