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:

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