Add on additional fields to all log entries

[bcharna]

Problem

#255 and #272 highlight the problem. To summarize, it's great that lograge by default tacks on fields like 'action', 'controller', 'format', etc onto the controller log entries. But it's unfortunate that other log entries triggered throughout the request do not have these fields tacked on.

Goal

The goal of this PR is to make it so that you can opt into having all log entries (even those triggered from third-party gems) within a request have the default fields that lograge typically adds on, plus any fields added on by the user's supplied config.lograge.custom_payload by using a special formatter.

Example Config

Below is an example of how the newly added formatter, Lograge::LogStashLoggerFormatters::MergedWithLogragePayload, can be used to add all the fields on all the log entries.

require 'lograge/logstash_logger_formatters/merged_with_lograge_payload'

Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Logstash.new
  config.lograge.custom_payload do |controller|
    request = controller.request
    {
      remote_ip: request.remote_ip,
      request_id: request.request_id
      # ...
    }
  end
  config.lograge.logger = LogStashLogger.new(
    type: :multi_delegator,
    formatter: Lograge::LogStashLoggerFormatters::MergedWithLogragePayload,
    outputs: [
      { type: :file, path: 'log/development.log' },
      { type: :tcp, host: 'listener.example.com', port: 5050 }
    ],
    customize_event: ->(event) {
      event['token'] = 'logstash_service_token'
    }
  )
  Rails.logger = config.lograge.logger
end

Open Questions

I have left a couple of TODOs in the code that I think warrant more discussion; please feel free to comment and we can come to a consensus on the right approach.

Limitations

Logs triggered from middleware that is run before the Rails application is run will not get the additional fields tacked on because this change relies on the start_processing.action_controller event. As far as I can tell, there is no trivial fix for this, though this can be revisited later.

Callouts

1. Provided this approach is on the right path, I will add to the specs and README.
2. Using a formatter in this way with logstash-logger doesn't totally work out of the box, I have submitted a fix PR: Instantiate custom formatter classes with customize_event keyword arg dwbutler/logstash-logger#155. If there is lag in getting that merged, I think I can outline a temporary workaround.

[Nowaker]

@bcharna I think I'm looking for something similar to you, at least conceptually, but I'm having a trouble applying your approach to my desired goal, which is simpler than yours. My goal is to trigger another line of log, similar to one that Lograge would trigger. Not looking for any third party loggers like LogStashLogger. I just want to trigger what Lograge would normally trigger - including my custom paylods and options.

    config.lograge.enabled = true
    config.lograge.custom_payload do |controller|
      { ... } # some custom stuff
    end
    config.lograge.custom_options = lambda do |event|
      hash = {
        params: event.payload[:params].except(:controller, :action, :format, :id),
      }

      if e = event.payload[:exception_object]
        Exceptions.to_lograge e, hash, event
      end

      hash
    end

Any ideas how I would do it? I don't have any Rails.configuration.lograge.logger because all I want is the standard Lograge output.

[Nowaker]

@bcharna Pardon my ignorance - I didn't spot it was a PR. Thought it was just an issue. ;) I set what you did there and will repurpose it for my use. Thank you for this contribution.

[Nowaker]

@bcharna Here's my feedback on your PR:

1. prepend_before_action is problematic because my custom_payload method accesses data that my custom before_action set in Application Controller. For this reason, RequestStore.store[:lograge_custom_payload] does not have the same data Lograge has when generating my log line. What would be the right approach to execute custom_payload on demand, when logger is actually called?
2. unsure if MergedWithLogragePayload should care about the user's custom_options - it should! custom_options is no different from custom_payload. I have my custom stuff in custom_payload but I use custom_options simultaneously for adding exception information if middleware sets it.
3. it's not ideal that the user's custom_payload method would be called twice - not ideal but better than nothing! I wouldn't care about it, honestly.

[bcharna]

hey @Nowaker, thank you for these notes. I'm a bit far removed from this PR and likely will not be able to dig deeper into it anytime soon. But I'd be happy if someone can pick it up and improve it or gain some traction on supporting something along these lines.