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.
