Log4r - output is unordered

Question

I'm a newbie in Rails, and I had a problem with my Rails project. I used Log4r for my logger. I also used config for Log4r at How to configure Log4r with Rails 3.0.x? . But when I send some request at the same time, the output of Log4r has error. It is unordered. :(

Example about error output log file:

Started GET "/task_results.json" for 172.29.73.182 at 2013-06-17 17:36:38 +0700
Processing by TaskResultsController#index as JSON

Started GET "/favicon.ico" for 172.29.73.182 at 2013-06-17 17:36:38 +0700
Processing by ApplicationController#missing_page as 
  Parameters: {"path"=>"favicon"}
Completed 404 Not Found in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)
  [1m [36m (994.0ms) [0m   [1mSELECT task_result_id,task_id,worker_id,product_id,passed,date_time,details FROM task_results ORDER BY task_result_id DESC; [0m
Completed 200 OK in 8656ms (Views: 0.2ms | ActiveRecord: 994.0ms)

And I wanna ask that how can I config Log4r to synchronize output? Or how can I fix my problem?

Answer 1

ruby is single-threaded, so I assume you are running your rails app on a server like unicorn?

The only solution I can think of is timestamps (with micro seconds) and not using the multi-line Rails log output which is not suitable for anything but single requests in dev environments. But even this does not guarantee "ordered" logs because they can be written when the request was served or at a random time afterwards when the buffer was flushed again.

This is an in-depth tutorial on how to use Log4r that also shows how to get custom timestamps into your logs and have all the important information on a single line. This prevents logs from other requests writing inside your main request and you can have a timestamp resolution of microseconds and order afterwards manually. However the order should not matter if you are running concurrent app-servers because the order is not guaranteed there anyway.