CODEWITHSUNDEEP
ruby-on-railsruby-on-rails-3apachepassenger
XP84
XP84

Reputation: 1350

Rails production.log (using Passenger) being written to by multiple processes, can't be parsed

Here's a snippet of my production.log:

Started GET "/product/514034/754240" for XX.XX.202.138 at 2012-06-21 11:52:28 -0700


Started GET "/product/614409/666897" for XX.XX.228.38 at 2012-06-21 11:52:28 -0700
Processing by ProductsController#show as HTML
  Parameters: {"category_id"=>"514034", "product_id"=>"754240"}
Processing by ProductsController#show as HTML
  Parameters: {"category_id"=>"614409", "product_id"=>"666897"}
Logged in 2940659 via auth cookie
Logged in 585210 via auth cookie
[e3e3fc56bb6bd137741b269ee397683c] [2940659] Read fragment views/global-caches/header (0.7ms)
[e3e3fc56bb6bd137741b269ee397683c] [2940659]   Rendered shared/_email_form.html.haml (0.7ms)
[d81bb986be5acc0277c0c9e11b414249] [585210] Read fragment views/global-caches/sharebar-message (0.7ms)
[d81bb986be5acc0277c0c9e11b414249] [585210]   Rendered shared/_email_form.html.haml (0.7ms)
...

As you can see, it's logging two concurrent sessions of two different users simultaneously to the same log file. This makes it impossible to parse my logs and determine, for example, the time it took to generate each kind of page, because the entries are not in the expected order of: 

Started GET "/URL/BLAH" for IP at DATE
... stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)

Instead I get an unpredictable interleaved log like this:

Started GET "/URL/BLAH" for IP at DATE

Started GET "/URL/BLAH" for IP at DATE
... stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)
...stuff...
Completed 200 OK in XXms (ActiveRecord: YY.Yms)

So it's impossible to match the "completeds" with the "Started."

What I'd like is a way to have each child process write to its own log or something. Or if it's possible a way to write the each pageview's log atomically, but that might be impossible or difficult or hurt performance.

Upvotes: 1

Views: 739

Answers (1)

Rodion
Rodion

Reputation: 521

Rails 3.2 provides nice option config.log_tag

You can add to your production.rb:

config.log_tags = [ lambda { Time.now.to_i }]

So each line in your logs will be prepended by numbers. Example:

[1351867173] Started GET "/" for 127.0.0.1 at 2012-11-02 16:39:33 +0200
[1351867173] Processing by RecipesController#main as HTML

Logs are still shuffled, but now we can normalize, order them.

sort -f -s -k1.1,1.11 production.log | sed 's/^.............//' > sorted_production.log

(Sorter by first symbols (by timestamp) and remove timestamp by sed)

Now logs are easy to analyze.

In addition there is fix on related issue https://github.com/rails/rails/pull/7317 in rails 3.2.9
So keep this in mind.
Sorry for bad English... )

Upvotes: 3

Related Questions