#
# Copyright (c) 2012 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

    # 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
    #
    # @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
    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
    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)
      logger = env["rack.logger"]
      env["rack.logging.enabled"] = enabled = logging_enabled?(logger, env)

      began_at = Time.now
      log_request_begin(logger, env) if enabled
      status, header, body = @app.call(env)
      if env['sinatra.error'] && !env['sinatra.error.handled']
        log_exception(logger, env['sinatra.error'])
      end
      log_request_end(logger, env, status, header, body, began_at) if enabled

      return [status, header, body]
    rescue Exception => e
      log_exception(logger, e)
      raise
    end

    private

    # 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["HTTP_X_DEBUG"]
        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

    # 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

      shard_info = 'Shard: ' + (env['HTTP_X_SHARD'] || 'default').to_s + ';'

      params = [
        env['REQUEST_METHOD'],
        env['PATH_INFO'],
        query_info,
        remote_addr,
        sess,
        shard_info,
        env['rack.request_uuid'] || ''
      ]

      logger.info 'Processing %s "%s%s" (for %s)  %s %s Request ID: %s' % params
    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

      # Downcase keys in the headers Hash for case-insensitive comparisons
      safe_headers = Hash[*headers.map {|k,v| [k.downcase, v]}.flatten]

      content_length = if safe_headers['content-length']
        safe_headers['content-length']
      else
        if body.is_a?(Array)
          body.reduce(0) {|accum, e| accum += e.bytesize}
        elsif body.is_a?(String)
          body.bytesize
        else
          '-'
        end
      end

      params = [
        duration,
        "#{status} #{Rack::Utils::HTTP_STATUS_CODES[status]}",
        content_length.to_s,
        env['rack.request_uuid'] || ''
      ]

      logger.info 'Completed in %dms | %s | %s bytes | Request ID: %s' % params
    end

    # Log exception
    #
    # @param [Object] logger for Rack
    # @param [Exception] exception to be logged
    #
    # @return [TrueClass] always true
    def log_exception(logger, exception)
      msg = ["#{exception.class} - #{exception.message}", *exception.backtrace].join("\n")
      logger.error(msg)
    rescue
      #no-op, something is seriously messed up by this point...
    end
  end
end