Request logging: around_filters can't see error responses!


#1

Hello,

I want to emit a structured log entry (in YAML) for every request that
hits my Rails app. For example, an entry in this log would look
something like:


SYSTEM_TIME: 0.0166666666666667
USER_TIME: 0.0999999999999996
DB_TIME: 0.00247621536254883
REAL_TIME: 0.091976
STATUS_CODE: 500
SESSION_ID: 64ad46a8841c66bbf64e93335cedc50d
REQUEST_ID: 32d6a42f-da58-43e2-ab27-09d3e2a775cb
RESPONSE_BODY_SIZE: 7001
REMOTE_IP: 127.0.1.1
TIMESTAMP: 2007-04-23 12:05:41.555780 -07:00
USER_AGENT: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.3) Gecko/
20060601 Firefox/2.0.0.3 (Ubuntu-edgy)
USER_ID: 102
QUERY_STRING:
PATH: /home
IS_AJAX: false
PARAMS: {}

I tried doing this using an around_filter. The #before part stored
the time and generated a request ID, and the #after part dumped all
the remaining data from the controller.request and controller.response
objects into this log. This worked great, except in the case that any
error occurred. In this case, Rails would run my after filter before
the status was set to 500, so my log would never see STATUS_CODE: 500.

My second try was to wrap/override ActionController::Base#process:

class ActionController::Base
unless instance_methods.include?(“original_process”)
alias_method :original_process, :process

    def process(*args)
        # do "before" stuff

        ret = framework_process(*args)

        # do "after" stuff
        return ret
    end
end

end

This works, but naturally I would prefer not to muck with the guts of
Rails if I can help it. Is there any better way to accomplish my
goal?

Josh