Using keep_original_rails_log sends Rails original logs to LogStash and lograge'd to config.lograge.logger

[f3ndot]

Apologies if this issue is a bit messy.

Description

So it would appear, contrary to the README and original PR https://github.com/roidrage/lograge/pull/61, using keep_original_rails_log does the opposite of what I'd expect.

Without it, lograge performs as expected, simplifying the rails log output into one line and sending it off to whatever the logstash config is (in my case TCP port 5050 which I pipe to stdout via netcat for test). For example, here's me visiting the root page:

$ nc -l 5050
{"method":"GET","path":"/","format":"html","controller":"ApplicationController","action":"show","status":200,"duration":124.09,"view":0.13,"@timestamp":"2017-08-24T22:47:06.488Z","@version":"1","message":"[200] GET / (ApplicationController#show)"}

Now, strangely, when I enable keep_original_rails_log, setting the logger to be my rails server stdout like so:

Rails.application.configure do
  # Allows developers to see logs in stdout
  config.lograge.keep_original_rails_log = true
  config.lograge.logger = ActiveSupport::Logger.new(STDOUT)
end

I now see the original verbose Rails logs in my logstash server:

$ nc -l 5050
{"message":"Started GET \"/\" for ::1 at 2017-08-24 18:57:40 -0400","@timestamp":"2017-08-24T18:57:40.897-04:00","@version":"1","severity":"INFO","host":"Justins-MacBook-Pro-5.local"}
{"message":"Processing by ApplicationController#show as HTML","@timestamp":"2017-08-24T18:57:40.904-04:00","@version":"1","severity":"INFO","host":"Justins-MacBook-Pro-5.local"}
{"message":"Completed 200 OK in 127ms (Views: 0.1ms)\n\n","@timestamp":"2017-08-24T18:57:41.031-04:00","@version":"1","severity":"INFO","host":"Justins-MacBook-Pro-5.local"}

And the lograged logs in my stdout!!

$ be rails s -p 3333                                                                             1 ↵
=> Booting Puma
=> Rails 5.1.3 application starting in development on http://localhost:3333
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.10.0 (ruby 2.4.1-p111), codename: Russell's Teapot
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3333
{"method":"GET","path":"/","format":"html","controller":"ApplicationController","action":"show","status":200,"duration":124.09,"view":0.13,"@timestamp":"2017-08-24T22:47:06.488Z","@version":"1","message":"[200] GET / (ApplicationController#show)"}

Expected

Turning on keep_original_rails_log will send the original Rails logs to whatever config.lograge.logger is set to while also continuing to send the lograge'd logs to whatever is in logstash configs.

Actual

I get the opposite: config.lograge.logger gets the lograge'd logs whilst whatever logstash is configured as gets the original Rails logs (albeit in the LogStash format)

Details

• Rails 5.1.3 (API-only mode)
• Ruby 2.4.1
• Lograge 0.5.1
• Logstash-event 1.2.02
• Logstash-logger 0.25.1

Example App

Minimal demo app here. Specific lines where bug occurs here

For the lazy, here is a poor made screenshot showing the issue on my local machine:

[f3ndot]

A little follow up, I was still able to reproduce with Lograge 0.6.0. I've also discovered log entries I've added myself into the application correctly route to the logstash destination.

Eg: with the following commit added to my demo app: https://github.com/f3ndot/rails_5_api_bad_logs/commit/131963b5e78c3f6c40bd89c9103d6c700b58e5c2

# This is nc -l 5050. Note the 3rd entry is my logger.info() call
{"message":"Started GET \"/\" for 127.0.0.1 at 2017-08-27 14:35:49 -0400","@timestamp":"2017-08-27T14:35:49.200-04:00","@version":"1","severity":"INFO","host":"DESKTOP-IG5T4T1"}
{"message":"Processing by ApplicationController#show as HTML","@timestamp":"2017-08-27T14:35:49.216-04:00","@version":"1","severity":"INFO","host":"DESKTOP-IG5T4T1"}
{"message":"Oh hey this is a test","@timestamp":"2017-08-27T14:35:49.217-04:00","@version":"1","severity":"INFO","host":"DESKTOP-IG5T4T1"}
{"message":"Completed 200 OK in 171ms (Views: 0.2ms)\n\n","@timestamp":"2017-08-27T14:35:49.388-04:00","@version":"1","severity":"INFO","host":"DESKTOP-IG5T4T1"}

And yet, lograge's request line still appears in the STDOUT:

{"method":"GET","path":"/","format":"html","controller":"ApplicationController","action":"show","status":200,"duration":170.76,"view":0.16,"@timestamp":"2017-08-27T18:35:49.389Z","@version":"1","message":"[200] GET / (ApplicationController#show)"}

I hope this help points in the right direction for what the root cause may be.

Unfortunately I don't know enough about the internals of Rails logging to sufficiently and confidently prepare a fix myself.

[benbarber]

You can configure logstash-logger to output to both logstash and stdout rather that using lograge, see https://github.com/dwbutler/logstash-logger#multi-logger

    config.logstash.type = :multi_logger
    config.logstash.io = STDOUT
    config.logstash.outputs = [
      {
        type: :io,
        formatter: ActiveSupport::Logger::SimpleFormatter.new
      },
      {
        type: :udp,
        port: 5228,
        host: 'localhost'
      }
    ]