#
# 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.
    #
    # @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
    def initialize(app, options = {})
      @app = app
      @only = options[:only]
      @except = options[:except]
    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, 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"]
      env["HTTP_X_DEBUG"] || [Logger::DEBUG, :debug].include?(logger.level) ||
          @only && @only.any? { |o| o.is_a?(Regexp) ? (path =~ o) : (path == o) } ||
          @except && @except.none? { |e| e.is_a?(Regexp) ? (path =~ e) : (path == e) }
    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['HTTP_X_FORWARDED_FOR'] || env["REMOTE_ADDR"] || "-"
      remote_addr = remote_addr.ljust(15)

      # Log the fact that a query string was present, but do not log its contents
      # because it may have sensitive data.
      if (query = env["QUERY_STRING"]) && !query.empty?
        query_info = '?...'
      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 %Q{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, 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}
        else
          body.bytesize
        end
      end

      params = [
        duration,
        "#{status} #{Rack::Utils::HTTP_STATUS_CODES[status]}",
        content_length.to_s,
      ]

      logger.info %Q{Completed in %dms | %s | %s bytes} % 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