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: 195
logging
|ruby-on-rails
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