class ApiHammer::RequestLogger
Rack middleware for logging. much like Rack::CommonLogger but with a log message that isn't an unreadable mess of dashes and unlabeled numbers.
two lines:
-
an info line, colored prettily to show a brief summary of the request and response
-
a debug line of json to record all relevant info. this is a lot of stuff jammed into one line, not pretty, but informative.
Constants
- LARGE_BODY_SIZE
Public Class Methods
new(app, logger, options={})
click to toggle source
options
-
:logger
-
:filter_keys - array of keys to filter from logged bodies
-
:log_bodies - true, false, :on_error
Calls superclass method
# File lib/api_hammer/request_logger.rb, line 51 def initialize(app, logger, options={}) @options = options super(app, logger) end
Public Instance Methods
call(env)
click to toggle source
# File lib/api_hammer/request_logger.rb, line 56 def call(env) began_at = Time.now began_ns = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond) # this is closed after the app is called, so read it before env["rack.input"].rewind request_body = env["rack.input"].read env["rack.input"].rewind if @logger && @logger.formatter.respond_to?(:current_tags) log_tags = @logger.formatter.current_tags.dup end request = Rack::Request.new(env) request_uri = Addressable::URI.new( :scheme => request.scheme, :host => request.host, :port => request.port, :path => request.path, :query => (request.query_string unless request.query_string.empty?) ) status, response_headers, response_body = @app.call(env) response_headers = ::Rack::Utils::HeaderHash.new(response_headers) body_proxy = ::Rack::BodyProxy.new(response_body) do log(env, request_uri, request_body, status, response_headers, response_body, began_at, began_ns, log_tags) end [status, response_headers, body_proxy] end
log(env, request_uri, request_body, status, response_headers, response_body, began_at, began_ns, log_tags)
click to toggle source
# File lib/api_hammer/request_logger.rb, line 86 def log(env, request_uri, request_body, status, response_headers, response_body, began_at, began_ns, log_tags) now_ns = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond) request = Rack::Request.new(env) response = Rack::Response.new('', status, response_headers) request_headers = env.map do |(key, value)| http_match = key.match(/\AHTTP_/) if http_match name = http_match.post_match.downcase {name => value} else name = %w(content_type content_length).detect { |sname| sname.downcase == key.downcase } if name {name => value} end end end.compact.inject({}, &:update) data = { 'request_role' => 'server', 'bound' => 'inbound', 'request' => { 'method' => request.request_method, 'uri' => request_uri.normalize.to_s, 'headers' => request_headers, 'remote_addr' => env['HTTP_X_FORWARDED_FOR'] || env["REMOTE_ADDR"], # these come from the OAuthenticator gem/middleware 'oauth.authenticated' => env['oauth.authenticated'], 'oauth.consumer_key' => env['oauth.consumer_key'], 'oauth.token' => env['oauth.token'], # airbrake 'airbrake.error_id' => env['airbrake.error_id'], }.reject { |k,v| v.nil? }, 'response' => { 'status' => status.to_s, 'headers' => response_headers, 'length' => response_headers['Content-Length'] || response_body.to_enum.map(&:bytesize).inject(0, &:+), }.reject { |k,v| v.nil? }, 'processing' => { 'began_at' => began_at.utc.to_f, 'duration' => (now_ns - began_ns) * 1e-9, 'activesupport_tagged_logging_tags' => log_tags, }.merge(env['request_logger.info'] || {}).merge(Thread.current['request_logger.info'] || {}).reject { |k,v| v.nil? }, } response_body_string = response_body.to_enum.to_a.join('') body_info = [['request', request_body, request.content_type], ['response', response_body_string, response.content_type]] if log_bodies(status) body_info.map do |(role, body, content_type)| parsed_body = ApiHammer::Body.new(body, content_type) content_type_attrs = ApiHammer::ContentTypeAttrs.new(content_type) if content_type_attrs.text? if (400..599).include?(status.to_i) || body.size < LARGE_BODY_SIZE # log bodies if they are not large, or if there was an error (either client or server) data[role]['body'] = parsed_body.filtered(@options.reject { |k,v| ![:filter_keys].include?(k) }).jsonifiable.body else # otherwise, log id and uuid fields body_object = parsed_body.object sep = /(?:\b|\W|_)/ hash_ids = proc do |hash| hash.reject { |key, value| !(key =~ /#{sep}([ug]u)?id#{sep}/ && value.is_a?(String)) } end if body_object.is_a?(Hash) body_ids = hash_ids.call(body_object) elsif body_object.is_a?(Array) && body_object.all? { |e| e.is_a?(Hash) } body_ids = body_object.map(&hash_ids) end data[role]['body_ids'] = body_ids if body_ids && body_ids.any? end end end end Thread.current['request_logger.info'] = nil json_data = JSON.dump(data) dolog = proc do began_s = began_at.strftime('%Y-%m-%d %H:%M:%S %Z') @logger.info "#{bold(intense_cyan('<'))} #{status_s(status)} : #{bold(intense_cyan(request.request_method))} #{intense_cyan(request_uri.normalize)} @ #{intense_cyan(began_s)}" @logger.info json_data end # do the logging with tags that applied to the request if appropriate if @logger.respond_to?(:tagged) && log_tags @logger.tagged(log_tags, &dolog) else dolog.call end end