#
# Copyright (c) 2012-2016 RightScale Inc
#
# Permission is hereby granted, free of charge, to any person obtaining
# a copy of this software and associated documentation files (the
# "Software"), to deal in the Software without restriction, including
# without limitation the rights to use, copy, modify, merge, publish,
# distribute, sublicense, and/or sell copies of the Software, and to
# permit persons to whom the Software is furnished to do so, subject to
# the following conditions:
#
# The above copyright notice and this permission notice shall be
# included in all copies or substantial portions of the Software.
#
# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
# EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
# MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
# NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
# LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
# OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
# WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.

require 'logger'
require 'rack'

module RightSupport::Rack

  # 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['rack.logger'] 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.
  class RequestLogger

    # limit exception backtrace length; usually only the first few lines are
    # significant. the same error dumped repeatedly can make grepping difficult.
    BACKTRACE_LIMIT = 10

    # for debug-mode only logging. debug-mode can also be enabled by the
    # "X-Debug=<anything>" header.
    DEBUG_MODE_ENV_KEY     = 'rack.debug-mode'.freeze
    DEBUG_MODE             = ::ENV['DEBUG_MODE'] == 'true'
    DEBUG_MODE_HTTP_HEADER = 'HTTP_X_DEBUG'

    # defaults to STDERR by Rack but usually overridden to use syslog, etc.
    RACK_LOGGER = 'rack.logger'.freeze

    # indicates whether current request is enabled for logging by filter, etc.
    RACK_LOGGING_ENABLED = 'rack.logging.enabled'.freeze

    # 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.
    NORMALIZE_40X = [401, 403, 404]

    # Initialize an instance of the middleware, optionally providing a whitelist
    #  (:only) or a blacklist (:except) of path regexps to which request logging
    #  will apply.
    #
    # @param [Object] app inner application or middleware layer; must respond to
    #  #call.
    # @param [Hash] options
    # @option options [Array] :only log for these path Regexps unless in debug
    #  mode.
    # @option options [Array] :except log except for these path Regexps unless
    #  in debug mode; this option is ignored if :only is provided.
    # @option options [Array] :include_query_string log the contents of the
    #  query string.
    # @option options [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.
    # @option options [TrueClass|FalseClass] :normalize_40x to remove detail
    #  from some 40x responses for security reasons. default=false.
    # @option options [TrueClass|FalseClass] :normalize_40x_set_cookie 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.
    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?
    end

    # Add a logger to the Rack environment and call the next middleware.
    #
    # @param [Hash] env Rack environment
    # @option env [TrueClass|FalseClass] 'rack.logging.enabled' in Rack
    #  environment to indicate whether logging is enabled for this request for
    #  use by other middleware in the call chain.
    # @option env [TrueClass|FalseClass] 'sinatra.error' is set by Sinatra to
    #  pass error info (exception object) to handlers.
    # @option env [TrueClass|FalseClass] 'sinatra.error.handled' 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).
    #
    # @return [Object] always returns whatever value is returned by the next
    #  layer of middleware
    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

    # provides a canonical representation of a header key that is acceptable to
    # Rack, etc.
    def self.canonicalize_header_key(key)
      key.downcase.gsub('_', '-')
    end

    # @return [String] header value by canonical key name, if present.
    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

    # safely sets a header value by first locating any existing key by canonical
    # search.
    #
    # @param [Hash] headers to modify
    # @param [String] key for header
    # @param [String] value for header
    # @return [Hash] updated headers
    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

    # Formats a concise error message with limited backtrace, etc.
    #
    # @param [Exception] e to format
    #
    # @return [String] formatted error
    def self.format_exception_message(e)
      trace = e.backtrace || []
      if trace.size > BACKTRACE_LIMIT
        trace = trace[0, BACKTRACE_LIMIT] << '...'
      end
      kind = e.class.name
      if (msg = e.message) && !msg.empty? && msg != kind
        kind = "#{kind}: #{msg}"
      end
      [kind, *trace].join("\n")
    end

    # @return [String] accepted/generated request UUID or else 'missing' to
    #  indicate that the RequestTracker middleware is missing.
    def self.request_uuid_from_env(env)
      env[RequestTracker::REQUEST_UUID_ENV_NAME] || 'missing'
    end

    private

    # determines if debug-mode is enabled for the current request by environment
    # variable override or by specific X-Debug header in request.
    #
    # note that the legacy code accepted any value for the debug header so long
    # as it was not nil.
    def debug_enabled?(env)
      DEBUG_MODE || !env[DEBUG_MODE_HTTP_HEADER].nil?
    end

    # Determine whether logging enabled for given request
    #
    # @param [Object] logger for Rack
    # @param [Hash] env Rack environment
    #
    # @return [Boolean] enabled or not
    def logging_enabled?(logger, env)
      path = env["PATH_INFO"]

      # the request can always ask for debugging
      if env[DEBUG_MODE_ENV_KEY]
        true
      # some apps have a blacklist of boring requests (e.g. health checks)
      elsif @except.any? { |e| e.is_a?(Regexp) ? (path =~ e) : (path == e) }
        false
      # some apps have a whitelist of interesting requests
      elsif @only.any? { |o| o.is_a?(Regexp) ? (path =~ o) : (path == o) }
        true
      # last chance: if whitelist is empty, then we log everything
      else
        @only.empty?
      end
    end

    # @return [String] accepted/generated request UUID or else 'missing' to
    #  indicate that the RequestTracker middleware is missing.
    def request_uuid_from_env(env)
      self.class.request_uuid_from_env(env)
    end

    # Log beginning of request
    #
    # @param [Object] logger for Rack
    # @param [Hash] env Rack environment
    #
    # @return [TrueClass] always true
    def log_request_begin(logger, env)
      # Assuming remote addresses are IPv4, make them all align to the same
      # width
      remote_addr = env['HTP_X_REAL_IP'] ||
                    env['HTTP_X_FORWARDED_FOR'] ||
                    env["REMOTE_ADDR"] || "-"
      remote_addr = remote_addr.ljust(15)

      # If we're not logging the contents of the query string we only log the fact that a query
      # string was present.
      if (query = env["QUERY_STRING"]) && !query.empty?
        query_info = @include_query_string ? "?#{CGI::escape(query)}" : '?...'
      else
        query_info = ''
      end

      # Session
      if env['global_session']
        cookie = env['global_session']
        info = [ env['global_session'].id,
                 cookie.keys.map{|k| %{"#{k}"=>"#{cookie[k]}"} }.join(', ') ]
        sess = %Q{Session ID: %s, Session Data: {%s}, } % info
      else
        sess = ""
      end

      logger.info '[%s] Started %s "%s%s" (for %s), %sShard: %s' % [
        request_uuid_from_env(env),
        env['REQUEST_METHOD'],
        env['PATH_INFO'],
        query_info,
        remote_addr,
        sess,
        env['HTTP_X_SHARD'] || 'default'
      ]
    end

    # Log end of request
    #
    # @param [Object] logger for Rack
    # @param [Hash] env Rack environment
    # @param [Fixnum] status of the Rack request
    # @param [Time] began_at time of the Rack request beginning
    #
    # @return [TrueClass] always true
    def log_request_end(logger, env, status, headers, body, began_at)
      duration = (Time.now - began_at) * 1000
      unless content_length = self.class.header_value_get(headers, 'Content-Length')
        case body
        when Array
          content_length = body.reduce(0) {|accum, e| accum += e.bytesize}
        when String
          content_length = body.bytesize
        else
          content_length = '-'
        end
      end

      request_uuid = request_uuid_from_env(env)
      logger.info '[%s] Completed in %dms | %s | %s bytes' % [
        request_uuid,
        duration,
        "#{status} #{Rack::Utils::HTTP_STATUS_CODES[status]}",
        content_length.to_s
      ]

      # more detail, if appropriate.
      if env[DEBUG_MODE_ENV_KEY] && logger.debug?
        unless headers.nil? || headers.empty?
          logger.debug("[#{request_uuid}] #{headers.inspect}")
        end
        unless body.nil? || body.empty?
          body = Array(body) unless body.respond_to?(:each)
          body.each do |b|
            b = b.to_s.strip
            logger.debug("[#{request_uuid}] #{b}") unless b.empty?
          end
        end
      end
      true
    end

    # Log exception
    #
    # @param [Object] logger for Rack
    # @param [Exception] exception to be logged
    #
    # @return [TrueClass] always true
    def log_exception(logger, e)
      logger.error(self.class.format_exception_message(e))
    rescue
      # no-op; something is seriously messed up by this point...
    end
  end
end