Rails lograge and logstash request logging

application_controller.rb

  # For logging client IPs with lograge
  def append_info_to_payload(payload)
    super
    payload[:ip] = remote_ip(request)
  end

private

  def remote_ip(request)
    request.headers['HTTP_X_REAL_IP'] || request.remote_ip
  end

config_application.rb

    # less verbose logging
    # see https://github.com/roidrage/lograge
    # https://github.com/aetrion/lograge-tagged
    config.lograge.enabled = true
    config.lograge.custom_options = ->(event) {
      opts = {
        params: event.payload[:params],
        time:  %Q('#{event.time}'),
        remote_ip: event.payload[:ip]
        # end:  %Q('#{event.end}'),
        # name:  event.name
        # payload is a http://api.rubyonrails.org/classes/ActiveSupport/Notifications/Event.html
        # duration
        # transaction_id
      }
      if event.payload[:exception]
        quoted_stacktrace = %Q('#{Array(event.payload[:stacktrace]).to_json}')
        opts[:stacktrace] = quoted_stacktrace
        # will output as e.g.
        #   "stacktrace":"'[\"/Users/somedev/.rvm/gems/ etc.
        # no need to include the :exception payload as it is already output
        # by the 'error' key, e.g.
        #   "error":"ActionView::Template::Error:bootstrap/carousel.js isn't precompiled"
      end
      opts
    }
    # options
    # config.lograge.custom_options = lambda do |event|
    # # capture some specific timing values you are interested in
    #   {:name => "value", :timing => some_float.round(2)}
    # end
    # format
    # default
    # config.lograge.log_format = :lograge
    # with 'logstash-event' gem
    config.lograge.log_format = :logstash
    # with 'gelf' gem
    # config.lograge.log_format = :graylog2

Gemfile

  gem 'lograge' # more readable logs
    gem 'logstash-event' # for logstash json format
  gem 'mono_logger' # threadsafe logging

initializer_lograge.rb

require 'mono_logger'
module LogrageLogger
  class Rails
    def initialize(config, options = {})
      @config = config
      @options = options || {}
    end

    def set_logger
      Lograge::RequestLogSubscriber.logger = lograge_logger
    end

    private

    def lograge_logger
      logger = @options[:logger] || MonoLogger.new(log_file(@options))
      logger = ActiveSupport::TaggedLogging.new(logger) if defined?(ActiveSupport::TaggedLogging)
      logger.level = MonoLogger.const_get(log_level(@config)) unless @options[:logger]
      logger.formatter = Formatter.new
      logger
    end

    # wanted to use config.log_level but it wasn't working
    # so using Rails.appliccation.config.log_level
    def log_level(config)
      ([ENV['LOG_LEVEL'].to_s.upcase, ::Rails.application.config.log_level, "INFO"] & %w[DEBUG INFO WARN ERROR FATAL UNKNOWN]).compact.first
    end

    def log_file(options)
      options[:logfile] || 'log/requests.log'
    end

    class Formatter
      def call(severity, time, progname, msg)
        "#{msg}\n"
      end
    end

  end
end
module LogrageLogging
  class Railtie < ::Rails::Railtie
    config.after_initialize do
      ::LogrageLogger::Rails.new(config).set_logger
    end
  end
end

initializer_logstash.rb

raise "Need to check the monkeypatched stacktrace payload Instrumenter is still correct" unless Rails.version == '3.2.13'
# https://github.com/rails/rails/blob/3-2-stable/activesupport/lib/active_support/notifications/instrumenter.rb
# also see payload[:stacktrace] in config/application.rb
module ActiveSupport
  module Notifications
    class Instrumenter
      attr_reader :id

      def initialize(notifier)
        @id = unique_id
        @notifier = notifier
      end

      # Instrument the given block by measuring the time taken to execute it
      # and publish it. Notice that events get sent even if an error occurs
      # in the passed-in block
      def instrument(name, payload={})
        started = Time.now

        begin
          yield
        rescue Exception => e
          payload[:exception] = [e.class.name, e.message]
          # BF added the below line to include backtrace in lograge
          payload[:stacktrace] = e.backtrace
          raise e
        ensure
          @notifier.publish(name, started, Time.now, @id, payload)
        end
      end
    end
  end
end
# look into adding an exception object via middleware that we can
# use in the :append_info_to_payload method
# e.g. see
# https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/action_controller_catcher.rb#L7
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/error_lookup.rb#L7
# https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rails/middleware.rb#L13
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/railtie.rb
#  and https://github.com/airbrake/airbrake/blob/master/lib/airbrake/rack.rb#L44
# since there is a difference between what is available by a subscriber and a middleware
#  see https://github.com/roidrage/lograge/blob/master/lib/lograge.rb

Hi, thanks for this gist!

May I ask for the reason you give request.headers['HTTP_X_REAL_IP'] higher precedence to request.remote_ip, shouldn't it be the same as the last entry of REMOTE_ADDR?

@shunwen I think it depends on if you're behind a proxy or not