Class: ApiHammer::RequestLogger

Inherits:
Rack::CommonLogger
  • Object
show all
Includes:
RequestLoggerHelper, Term::ANSIColor
Defined in:
lib/api_hammer/request_logger.rb

Overview

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.

Constant Summary collapse

LARGE_BODY_SIZE = 
4096

Instance Method Summary collapse

Methods included from RequestLoggerHelper

#log_bodies, #status_s

Constructor Details

#initialize(app, logger, options = {}) ⇒ RequestLogger

options

  • :logger
  • :filter_keys - array of keys to filter from logged bodies
  • :log_bodies - true, false, :on_error


51
52
53
54
 
# File 'lib/api_hammer/request_logger.rb', line 51

def initialize(app, logger, options={})
  @options = options
  super(app, logger)
end

Instance Method Details

#call(env) ⇒ Object 



56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
 
# 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) ⇒ Object 



86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
 
# 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