Integrate Lograge one-line logging but figure out Rack exception reporting

[mberkowski]

Centralized logging would be helped by https://github.com/roidrage/lograge but something, probably Rack is still receiving exceptions and printing stacktraces to the logs unformatted. The result is inconsistent logs that still can't be parsed easily, and no other UMN orgs have found a solution yet.

Production logging config

In config/environments/production.rb:

  # Sane prod log formatting with lograge
  config.lograge.enabled = true
  # OPTIONAL to use JSON formatted logging
  config.lograge.formatter = Lograge::Formatters::Logstash.new

  config.lograge.custom_options = lambda do |event|
    {   
      exception: event.payload[:exception],
      exception_object: event.payload[:exception_object],
      # Convert backtrace into one string - \n is OK for JSON, but a different
      # joiner would be needed if we didn't use the Logstash/JSON format.
      backtrace: (event.payload[:exception_object].backtrace.join("\n") rescue nil)
    }   
  end 

The above works, but Rack (probably) is still putting stack traces without lograge formatting into the log. For example, the first line is lograge-formatted (stack trace trimmed down), followed by unformatted output:

I, [2019-11-19T13:52:58.628940 #26994]  INFO -- : [1c38c4a2-7738-435e-9f78-6ef2bfcd0867] {"method":"GET","path":"/catalog/nyu_2451_34636","format":"html","controller":"CatalogController
","action":"show","status":200,"duration":182.81,"view":132.28,"db":1.37,"exception":null,"exception_object":null,"@timestamp":"2019-11-19T19:52:58.628Z","@version":"1","message":"[200]
 GET /catalog/nyu_2451_34636 (CatalogController#show)"}                                                                                                                                  
I, [2019-11-19T13:52:58.798930 #26994]  INFO -- : [56e975e7-b731-4d51-8f7d-f2a2bade9c99] {"method":"GET","path":"/catalog/nyu_2451_34636/relations","format":"*/*","controller":"Relation
Controller","action":"index","status":200,"duration":23.51,"view":22.06,"db":0.0,"exception":null,"exception_object":null,"@timestamp":"2019-11-19T19:52:58.798Z","@version":"1","message
":"[200] GET /catalog/nyu_2451_34636/relations (RelationController#index)"}                                                                                                              
I, [2019-11-19T13:53:15.397877 #26994]  INFO -- : [2421f5ff-8b40-4bc1-a705-305c060b502c] {"method":"GET","path":"/catalog/nyu_2451_34636/admin","format":"html","controller":"CatalogCont
roller","action":"admin","status":500,"error":"RuntimeError: Some error!!!","duration":14.77,"view":0.0,"db":0.0,"exception":["RuntimeError","Some error!!!"],"exception_object":"Some er
ror!!!","@timestamp":"2019-11-19T19:53:15.397Z","@version":"1","message":"[500] GET /catalog/nyu_2451_34636/admin (CatalogController#admin)"} 
I, [2019-11-19T14:14:01.893440 #5406]  INFO -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc] {"method":"GET","path":"/catalog/nyu_2451_34636/admin","format":"html","controller":"CatalogContr
oller","action":"admin","status":500,"error":"RuntimeError: Some error!!!","duration":19.27,"view":0.0,"exception":["RuntimeError","Some error!!!"],"exception_object":"Some error!!!","b
acktrace":"/home/mjb/src/geo/geoportal/app/controllers/catalog_controller.rb:308:in `admin'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionpack-5.2.3/lib/action_control
ler/metal/basic_implicit_render.rb:6:in `send_action'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:194:in `process_action'\
n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/rendering.rb:30:in `process_action'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems
/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/activ
e_support/callbacks.rb:132:in `run_callbacks'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionpack-5.2.3/lib/abstract_controller/callbacks.rb:41:in `process_action'\n/ho
me/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionpack-5.2.3/lib/action_controller/metal/rescue.rb:22:in `process_action'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/
gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.3/lib/ac
tive_support/notifications.rb:168:in `block in instrument'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-...SNIP....run'\n/home/mjb/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/puma-4.0.1/lib/puma/thread_pool.rb:135:in `block in spawn_thread'","@timestamp":"2019-11-19
T20:14:01.893Z","@version":"1","message":"[500] GET /catalog/nyu_2451_34636/admin (CatalogController#admin)"}
#----------------------------------------------------------
# - UNFORMATTED OUTPUT FROM RACK
F, [2019-11-19T14:14:01.893776 #5406] FATAL -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc]   
F, [2019-11-19T14:14:01.893803 #5406] FATAL -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc] RuntimeError (Some error!!!):
F, [2019-11-19T14:14:01.893824 #5406] FATAL -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc]   
F, [2019-11-19T14:14:01.893847 #5406] FATAL -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc] app/controllers/catalog_controller.rb:308:in `admin'
I, [2019-11-19T14:14:01.907700 #5406]  INFO -- : [6faba4a1-9684-40b8-afa7-cfb6dc4c41fc] {"method":"GET","path":"/500","format":"html","controller":"ErrorsController","action":"internal_
server_error","status":500,"duration":13.33,"view":13.18,"exception":null,"exception_object":null,"backtrace":null,"@timestamp":"2019-11-19T20:14:01.907Z","@version":"1","message":"[500
] GET /500 (ErrorsController#internal_server_error)"}

RoutingError - make it not a fatal error

This is optional, but would avoid stack traces for basic 404s if dumped into an initializer.
roidrage/lograge#146

# Converts RoutingError to non-fatal, so they can be sanely logged by lograge gem
# From https://github.com/roidrage/lograge/issues/146
if Rails.application.config.lograge.enabled
  module ActionDispatch
    class DebugExceptions
      alias old_log_error log_error

      def log_error(request, wrapper)
        exception = wrapper.exception
        if exception.is_a?(ActionController::RoutingError)
          data = {
            method: request.env['REQUEST_METHOD'],
            path: request.env['REQUEST_PATH'],
            status: wrapper.status_code,
            error: "#{exception.class.name}: #{exception.message}"
          }
          formatted_message = Lograge.formatter.(data)
          logger(request).send(Lograge.log_level, formatted_message)
        else
          old_log_error request, wrapper
        end
      end
    end
  end
end