Adding a transaction ID to ruby-on-rails logs

Posted by Blue Warrior NFB on Server Fault See other posts from Server Fault or by Blue Warrior NFB
Published on 2013-11-12T21:01:01Z Indexed on 2013/11/12 21:56 UTC
Read the original article Hit count: 198

Filed under:
|

We have a RoR app (rails version 3.2.15 right now). As it has been getting busier, the log-files it's producing are becoming less and less useful for troubleshooting. When they come in like this, it's not a problem:

Started GET "/accounts/28088166/kittens/22894/rendered_png?file_id=5d3eaec77954a489b5ddd75143091767&kitten_store_id=9970569bbacf7b6dbeb4eb9295960d69&size=large" for 172.16.202.30 at 2013-11-12 13:45:00 +0000
Processing by KittenController#rendered_png as HTML
  Parameters: {"file_id"=>"5d3eaec77954a489b5ddd75143091767", "kitten_store_id"=>"9970569bbacf7b6dbeb4eb9295960d69",  "size"=>"large", "kitten_cam_id"=>"280941", "id"=>"kjlak357aw479607t"}
  Rendered text template (0.0ms)
Sent data   (1.8ms)
Completed 200 OK in 1037.4ms (Views: 1.4ms | ActiveRecord: 98.4ms)

Short request, quickly assembled, all the relevant log-lines are in one block.

However, not all of our code renders in 1037ms. There are a few calls that can exceed several seconds, and during that time several of these quicker ones can come in. When that happens, its very, very hard to identify which log-lines belong to which GET.

Sent data   (4.1ms)
Completed 200 OK in 767.4ms (Views: 3.2ms | ActiveRecord: 72.2ms)
Completed 200 OK in 2338.0ms (Views: 0.2ms | ActiveRecord: 0.0ms)

Ooookaaaay... which goes to what?

Is it possible to add something like a transaction-ID to these log-lines? The log-spam would be interspersed, but at least grep-magic would give me the unified entries that I need.

© Server Fault or respective owner

Related posts about logging

Related posts about ruby-on-rails