Class: RightSupport::Rack::RequestLogger

Inherits:
Object
  • Object
show all
Defined in:
lib/right_support/rack/request_logger.rb

Overview

A Rack middleware that logs information about every HTTP request received and every exception raised while processing a request.

The middleware can be configured to use its own logger, but defaults to using env for logging if it is present. If ‘rack.logger’ is not set, this middleware will set it before calling the next middleware. Therefore, RequestLogger can be used standalone to fulfill all logging needs, or combined with Rack::Logger or another middleware that provides logging services.

Constant Summary collapse

BACKTRACE_LIMIT =

default backtrace limit that can be overridden by configuring the middleware with a specific :backtrace_limit value.

10
DEBUG_MODE_ENV_KEY =

for debug-mode only logging. debug-mode can also be enabled by the “X-Debug=<anything>” header.

'rack.debug-mode'.freeze
DEBUG_MODE = 
::ENV['DEBUG_MODE'] == 'true'
DEBUG_MODE_HTTP_HEADER = 
'HTTP_X_DEBUG'
RACK_LOGGER =

defaults to STDERR by Rack but usually overridden to use syslog, etc.

'rack.logger'.freeze
RACK_LOGGING_ENABLED =

indicates whether current request is enabled for logging by filter, etc.

'rack.logging.enabled'.freeze
NORMALIZE_40X =

list of status codes that are ‘normalized’ when :normalize_40x=true normalization means stripping any developer-provided details to avoid leaking information about the service. overridden by DEBUG_MODE=true but specifically not affected by the ‘X-Debug’ header.

[401, 403, 404]

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

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

Initialize an instance of the middleware, optionally providing a whitelist

(:only) or a blacklist (:except) of path regexps to which request logging
will apply.

Parameters:

  • app (Object) —

    inner application or middleware layer; must respond to #call.

  • options (Hash) (defaults to: {})

Options Hash (options):

  • :only (Array) —

    log for these path Regexps unless in debug mode.

  • :except (Array) —

    log except for these path Regexps unless in debug mode; this option is ignored if :only is provided.

  • :include_query_string (Array) —

    log the contents of the query string.

  • :logger (Logger) —

    to override any previously set logger or nil. Rack sets a STDERR logger by default or it may be set by other framework middleware so this is only for when those are not used.

  • :normalize_40x (TrueClass|FalseClass) —

    to remove detail from some 40x responses for security reasons. default=false.

  • :normalize_40x_set_cookie (TrueClass|FalseClass) —

    to override the usual global session behavior of always responding with a ‘Set-Cookie’ header regardless of status code. defaults to having the same value as the :normalize_40x option.

  • :backtrace_limit (Integer) —

    maximum number of stack frames to display on error or negative for all (default = 10)



84
85
86
87
88
89
90
91
92
93
94
95
96
 
# File 'lib/right_support/rack/request_logger.rb', line 84

def initialize(app, options = {})
  @app = app
  @only = options[:only] || []
  @except = options[:except] || []
  # by default we don't log the query string contents because it may have sensitive data.
  @include_query_string = options[:include_query_string] || false
  @logger = options[:logger]
  @normalize_40x = !!options[:normalize_40x]
  @normalize_40x_set_cookie = options[:normalize_40x_set_cookie]
  @normalize_40x_set_cookie = @normalize_40x if @normalize_40x_set_cookie.nil?
  @backtrace_decoder = ::RightSupport::Notifier::Utility::BacktraceDecoder.new(
    backtrace_limit: Integer(options[:backtrace_limit] || BACKTRACE_LIMIT))
end

Class Method Details

.canonicalize_header_key(key) ⇒ Object

provides a canonical representation of a header key that is acceptable to Rack, etc.



190
191
192
 
# File 'lib/right_support/rack/request_logger.rb', line 190

def self.canonicalize_header_key(key)
  key.downcase.gsub('_', '-')
end

.format_exception_message(e, backtrace_decoder = nil) ⇒ String

Formats a concise error message with limited backtrace, etc.

Parameters:

  • e (Exception) —

    to format

  • e (Exception) —

    to format

Returns:

  • (String) —

    formatted error



234
235
236
237
238
239
240
241
242
243
 
# File 'lib/right_support/rack/request_logger.rb', line 234

def self.format_exception_message(e, backtrace_decoder = nil)
  backtrace_decoder ||= ::RightSupport::Notifier::Utility::BacktraceDecoder.new
  trace = ::RightSupport::Notifier::Utility::BacktraceDecoder.format_frames(
    backtrace_decoder.decode(e.backtrace))
  kind = e.class.name
  if (msg = e.message) && !msg.empty? && msg != kind
    kind = "#{kind}: #{msg}"
  end
  [kind, trace].join("\n")
end

.header_value_get(headers, key) ⇒ String

Returns header value by canonical key name, if present.

Returns:

  • (String) —

    header value by canonical key name, if present.



195
196
197
198
199
200
201
202
203
204
205
206
 
# File 'lib/right_support/rack/request_logger.rb', line 195

def self.header_value_get(headers, key)
  return nil unless headers
  key = canonicalize_header_key(key)
  value = nil
  headers.each do |k, v|
    if canonicalize_header_key(k) == key
      value = v
      break
    end
  end
  value
end

.header_value_set(headers, key, value) ⇒ Hash

safely sets a header value by first locating any existing key by canonical search.

Parameters:

  • headers (Hash) —

    to modify

  • key (String) —

    for header

  • value (String) —

    for header

Returns:

  • (Hash) —

    updated headers



215
216
217
218
219
220
221
222
223
224
225
226
 
# File 'lib/right_support/rack/request_logger.rb', line 215

def self.header_value_set(headers, key, value)
  headers ||= {}
  key = canonicalize_header_key(key)
  headers.each do |k, v|
    if canonicalize_header_key(k) == key
      key = k
      break
    end
  end
  headers[key] = value
  headers
end

.request_uuid_from_env(env) ⇒ String

Returns accepted/generated request UUID or else ‘missing’ to indicate that the RequestTracker middleware is missing.

Returns:

  • (String) —

    accepted/generated request UUID or else ‘missing’ to indicate that the RequestTracker middleware is missing.



247
248
249
 
# File 'lib/right_support/rack/request_logger.rb', line 247

def self.request_uuid_from_env(env)
  env[RequestTracker::REQUEST_UUID_ENV_NAME] || 'missing'
end

Instance Method Details

#call(env) ⇒ Object

Add a logger to the Rack environment and call the next middleware.

Parameters:

  • env (Hash) —

    Rack environment

Options Hash (env):

  • 'rack.logging.enabled' (TrueClass|FalseClass) —

    in Rack environment to indicate whether logging is enabled for this request for use by other middleware in the call chain.

  • 'sinatra.error' (TrueClass|FalseClass) —

    is set by Sinatra to pass error info (exception object) to handlers.

  • 'sinatra.error.handled' (TrueClass|FalseClass) —

    is true to prevent any additional error handlers in the call chain from processing an error that has already handled been handled (i.e. log and response) (default = false).

Returns:

  • (Object) —

    always returns whatever value is returned by the next layer of middleware



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
173
174
175
176
177
178
179
180
181
182
183
184
185
186
 
# File 'lib/right_support/rack/request_logger.rb', line 113

def call(env)
  # forward-declare in case of exception.
  enabled = true

  # override logger, if necessary.
  if @logger
    logger = env[RACK_LOGGER] = @logger
  else
    logger = env[RACK_LOGGER]
  end

  # determine if debug-mode is enabled.
  env[DEBUG_MODE_ENV_KEY] = debug_enabled?(env)

  # log request only when enabled.
  env[RACK_LOGGING_ENABLED] = enabled = logging_enabled?(logger, env)
  began_at = Time.now
  log_request_begin(logger, env) if enabled

  # next
  status, headers, body = @app.call(env)

  # log exception, if necessary.
  if env['sinatra.error'] && !env['sinatra.error.handled']
    if !enabled
      # after the fact but better than logging exception without its request.
      log_request_begin(logger, env)
      enabled = true
    end
    log_exception(logger, env['sinatra.error'])
  elsif !enabled && env[RACK_LOGGING_ENABLED]
    # controller can conditionally enable logging for the current request
    # even though by default such requests are not logged. an example is a
    # periodic request for a listing (scheduled tasks, etc.) that is only
    # logged when not empty.
    log_request_begin(logger, env)
    enabled = true
  end

  # respond identically to some 40Xs; do not reveal any internals by
  # varying the response headers or body (as developers tend to do for
  # debugging reasons). public APIs will receive such requests frequently
  # but this is generally not needed for internal APIs.
  #
  # note that it is important to *not* accept the "X-Debug" header override
  # and show more information in response ;)
  if @normalize_40x && !DEBUG_MODE && NORMALIZE_40X.include?(status)
    # note that ::Rack::CONTENT_LENGTH was not defined before rack v1.6+ :@
    headers = { 'Content-Length' => '0' }
    body = []
    env[DEBUG_MODE_ENV_KEY] = false  # disable any verbose debugging
  end

  # defeat global session renew, update and set-cookie for normalized 40x.
  # has no effect if the app is not using global session middleware.
  if @normalize_40x_set_cookie && NORMALIZE_40X.include?(status)
    env['global_session.req.renew'] = false
    env['global_session.req.update'] = false
  end

  # log response only when enabled.
  if enabled
    log_request_end(logger, env, status, headers, body, began_at)
  end

  return [status, headers, body]
rescue Exception => e
  if !enabled
    # after the fact but better than logging exception without its request.
    log_request_begin(logger, env)
  end
  log_exception(logger, e)
  raise
end