Rails 6 JSON logger (logstash format)

0. readme.md

What I want to have: all logs in JSON format, with additional tags and per-request tags (similar to java's MDC)

How to make it:

1. Use lograge with logstash-event to change default request logs
2. Make custom log formatter
3. Override ActiveSupport::TaggedLogging format
4. Add own error handlers with config.exceptions_app = self.routes
5. Override default logger at the right time

Use environment variables JSON_LOGGER = true/false and RAILS_LOG_LEVEL = info / debug / etc

Note that kibana by default use @timestamp attribute and it will be rounded to seconds. Since most of request will be handled within 1 second, then log messages to be in random order and very hard to use. I added time attribute that we can use as time field and it will be used with millisecond precision

We can use Thread.current.thread_variable_get(:logger_tags) to add extra attributes, e.g.

# in controller
add_logging_context(:user_email, current_user.email)

Request logs

before

Started GET "/app?test_user_phone=081339372389" for 127.0.0.1 at 2022-08-16 02:45:28 +0800
  ActiveRecord::SchemaMigration Pluck (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by WebappController#index as HTML
  Parameters: {"test_user_phone"=>"081339372389"}
  Rendering layout layouts/application.haml
  Rendering webapp/index.haml within layouts/application
  Rendered webapp/index.haml within layouts/application (Duration: 4.8ms | Allocations: 2793)
[Webpacker] Everything's up-to-date. Nothing to do
  Rendered layout layouts/application.haml (Duration: 58.6ms | Allocations: 14356)
Completed 200 OK in 67ms (Views: 60.7ms | ActiveRecord: 0.0ms | Allocations: 18325)

after

{"time":"2022-08-16T03:04:33.985160+08:00","level":"DEBUG","type":"default","request_id":"924c9ccd-8a83-476a-af25-3972c0143520","path":"/app","message":"\u001b[1m\u001b[36mActiveRecord::SchemaMigration Pluck (0.5ms)\u001b[0m  \u001b[1m\u001b[34mSELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC\u001b[0m"}
{"time":"2022-08-16T03:04:34.030925+08:00","level":"DEBUG","type":"default","request_id":"924c9ccd-8a83-476a-af25-3972c0143520","path":"/app","message":"Everything's up-to-date. Nothing to do"}
{"time":"2022-08-16T03:04:34.049406+08:00","level":"INFO","type":"default","request_id":"924c9ccd-8a83-476a-af25-3972c0143520","path":"/app","method":"GET","format":"*/*","controller":"WebappController","action":"index","status":200,"duration":39.37,"view":35.45,"db":0.0,"process_id":6064,"remote_ip":"127.0.0.1","host":"Pavel-MBP2.local","params":"{\"test_user_phone\":\"081339372389\"}","@timestamp":"2022-08-15T19:04:34.049Z","@version":"1","message":"[200] GET /app (WebappController#index)"}

SQL queries and Webpacker logs can be disabled with RAILS_LOG_LEVEL = INFO

404 errors

before

Started GET "/foo" for 127.0.0.1 at 2022-08-16 03:01:22 +0800
  
ActionController::RoutingError (No route matches [GET] "/foo"):
  
Processing by ErrorsController#not_found as HTML
  Rendering public/404.html
  Rendered public/404.html (Duration: 0.8ms | Allocations: 55)
Completed 404 Not Found in 6ms (Views: 4.8ms | Allocations: 974)

after

{"time":"2022-08-16T03:02:22.677391+08:00","level":"FATAL","type":"default","request_id":"f9f80671-5e15-495f-81c2-b6ba14f52768","path":"/foo","message":"ActionController::RoutingError (No route matches [GET] \"/foo\"):"}

Exceptions

before

Started GET "/app?test_user_phone=081339372389" for 127.0.0.1 at 2022-08-16 03:13:54 +0800
Processing by WebappController#index as */*
  Parameters: {"test_user_phone"=>"081339372389"}
Completed 500 Internal Server Error in 9ms (ActiveRecord: 0.0ms | Allocations: 3535)


  
NameError (undefined local variable or method `some_wrong_name' for #<WebappController:0x00000000007c38>

    some_wrong_name
    ^^^^^^^^^^^^^^^):
  
app/controllers/webapp_controller.rb:7:in `index'
Processing by ErrorsController#internal_server as */*
  Parameters: {"test_user_phone"=>"081339372389"}
Exception - /500?test_user_phone=081339372389
Completed 500 Internal Server Error in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms | Allocations: 374)

after

{"time":"2022-08-16T03:12:38.090739+08:00","level":"INFO","type":"default","request_id":"d629de0c-7419-404d-8e1f-fc9df33564f4","path":"/app","method":"GET","format":"*/*","controller":"WebappController","action":"index","status":500,"duration":8.47,"view":0.0,"process_id":6064,"remote_ip":"127.0.0.1","host":"Pavel-MBP2.local","params":"{\"test_user_phone\":\"081339372389\"}","exception":"NameError","@timestamp":"2022-08-15T19:12:38.090Z","@version":"1","message":"[500] GET /app (WebappController#index)"}
{"time":"2022-08-16T03:12:38.095591+08:00","level":"FATAL","type":"default","request_id":"d629de0c-7419-404d-8e1f-fc9df33564f4","path":"/app","message":"NameError (undefined local variable or method `some_wrong_name' for #\u003cWebappController:0x0000000000ab18\u003e\n\n    some_wrong_name\n    ^^^^^^^^^^^^^^^):\n  \napp/controllers/webapp_controller.rb:7:in `index'"}
{"time":"2022-08-16T03:12:38.096933+08:00","level":"INFO","type":"default","request_id":"d629de0c-7419-404d-8e1f-fc9df33564f4","path":"/app","message":"Exception - /500?test_user_phone=081339372389"}
{"time":"2022-08-16T03:12:38.097802+08:00","level":"INFO","type":"default","request_id":"d629de0c-7419-404d-8e1f-fc9df33564f4","path":"/500","method":"GET","format":"*/*","controller":"ErrorsController","action":"internal_server","status":500,"duration":0.88,"view":0.35,"process_id":6064,"remote_ip":"127.0.0.1","host":"Pavel-MBP2.local","params":"{\"test_user_phone\":\"081339372389\"}","@timestamp":"2022-08-15T19:12:38.097Z","@version":"1","message":"[500] GET /500 (ErrorsController#internal_server)"}

1. Gemfile

# add these

gem 'lograge'
gem 'logstash-event'

2. config application.rb

# setting exceptions_app to use own error handler

module MyAppName
  class Application < Rails::Application
    config.exceptions_app = self.routes
    # ...
  end
end

# put it at the bottom to make it work correctly
require_relative 'initializers/json_logger'

3. config routes.rb

Rails.application.routes.draw do
  # ...

  match '/404', to: 'errors#not_found', via: :all
  match '/500', to: 'errors#internal_server', via: :all
  match '/422', to: 'errors#unprocessable', via: :all
end

4. config initializers json_log_formatter.rb

# this class will be extended by ActiveSupport::TaggedLogging::Formatter
# https://github.com/rails/rails/blob/6-1-stable/activesupport/lib/active_support/tagged_logging.rb#L29
# and get method current_tags
# can be used without ActiveSupport::TaggedLogging, so we check respond_to?(:current_tags)

class JsonLogFormatter < Logger::Formatter
  def call(severity, _time, _progname, msg)

    log = {
      time: _time.iso8601(6),
      level: severity,
      type: "default",
    }

    if _progname
      log[:progname] = _progname
    end

    msg = msg&.strip

    # current_tags is provided
    if respond_to?(:current_tags) && !current_tags.empty?
      tagged = Rails.application.config.log_tags.zip(current_tags).to_h
      log.merge!(tagged)
    end

    # Thread.current.thread_variable_get(:logger_tags) - set and cleaned in app
    if Thread.current.thread_variable_get(:logger_tags).is_a?(Hash)
      log.merge!(Thread.current.thread_variable_get(:logger_tags))
    end

    begin
      # lograge provide json sting, not just a message
      parsed = JSON.parse(msg).symbolize_keys
      log.merge!(parsed)
    rescue JSON::ParserError
      log.merge!({message: msg})
    end
    log.to_json + "\n"
  rescue => error
    puts "Error in JsonLogFormatter #{error.class} - #{error.message}\n#{error.backtrace.join("\n")}"
  end
end

5. config initializers json_logger.rb

require_relative 'json_log_formatter'
require 'active_support/tagged_logging'

# ActiveSupport::TaggedLogging adds prefix with tags (https://github.com/rails/rails/blob/6-1-stable/activesupport/lib/active_support/tagged_logging.rb#L63)
# use this class to disable tags prefix in ActiveSupport::TaggedLogging output
# because we have custom json formatter that will put tags as properties
# before:
#   [request_id=aaaaa][path=/ping] some message
# after:
#.  some message
#
class TaggedLoggingWithoutFormatting
  module ResetFormatting
    def tags_text
      ""
    end
  end

  def self.new(logger)
    tagged_logger = ActiveSupport::TaggedLogging.new(logger)
    tagged_logger.formatter.extend(ResetFormatting)
    tagged_logger
  end
end

if ENV['JSON_LOGGER'[.present? && ENV['JSON_LOGGER'[ != 'false'
  Rails.application.configure do

    config.lograge.enabled = true
    config.lograge.formatter = Lograge::Formatters::Logstash.new
    config.lograge.ignore_actions = ['PingController#index', 'ErrorsController#not_found']

    hostname = Socket.gethostname

    config.lograge.custom_options = lambda do |event| # extra attributes for request logger
      {
        process_id: Process.pid,
        remote_ip: event.payload[:request].remote_ip,
        host: hostname,
        x_forwarded_for: event.payload[:x_forwarded_for],
        params: event.payload[:params].except('controller', 'action').to_json,
        exception: event.payload[:exception]&.first,
        request_id: event.payload[:headers]['action_dispatch.request_id'],
      }.compact
    end

    logger = ActiveSupport::Logger.new(STDOUT)
    logger.formatter = ::JsonLogFormatter.new

    if ENV['RAILS_LOG_LEVEL'].present?
      logger.level = ENV['RAILS_LOG_LEVEL'].downcase.to_sym
    end

    config.log_tags = [ :request_id, :path ]
    config.logger = TaggedLoggingWithoutFormatting.new(logger)

    config.log_formatter = ::Logger::Formatter.new

    if ENV['RAILS_LOG_LEVEL'].present?
      config.log_level = ENV['RAILS_LOG_LEVEL'].downcase.to_sym
    end
  end
end

6. app controllers application_controller.rb

class ApplicationController < ActionController::Base
  include CustomErrors
  # ...

  # todo: would be better to move this into middleware, clean it in beginning if request processing
  after_action :clear_logger_context

  def require_auth
    if current_user_phone.blank?
      redirect_to "/"
    else
      add_logging_context(:user_phone, current_user_phone) # example of extra tag
    end
  end
  
  # this can be used to add additional attributes 
  def add_logging_context(name, value)
    if !Thread.current.thread_variable_get(:logger_tags).is_a?(Hash)
      Thread.current.thread_variable_set(:logger_tags, {})
    end
    Thread.current.thread_variable_get(:logger_tags)[name.to_s] = value
  end

  def clear_logger_context
    Thread.current.thread_variable_set(:logger_tags, nil)
  end
end

7. app controllers errors_controller.rb

class ErrorsController < ApplicationController

  skip_before_action :require_auth
  skip_before_action :verify_authenticity_token

  # this part is optional, but I believe it helps to reduce 404 errors caused by strangers
  SPECIAL_TREATMENT_URLS = %w{
    /wp-login.php
    /index.php
    /phpinfo.php
    /.git/config
  }

  def not_found
    if SPECIAL_TREATMENT_URLS.include?(request.env['REQUEST_PATH']) || request.env['REQUEST_PATH'].start_with?("/wp-content/")
      headers_str = request.headers.select {|k,v| k =~ /^HTTP_/}.map do |key, val|
        "Header #{key}: #{val}"
      end.join("\n")
      logger.info("Special treamtment 404 handler - #{request.original_fullpath} (#{request.user_agent})\n#{headers_str}")
      redirect_to "https://speed.hetzner.de/10GB.bin"
    else
      render_404
    end
  end

  def render_404(exception = nil)
    if exception
      logger.info "Rendering 404 with exception: #{exception.class} - #{exception.message}"
      logger.info exception.backtrace.join("\n")
    end

    respond_to do |format|
      format.json { render json: {success: false, status: "404", error: "Page Not Found"}, status: 404 }

      format.all {
        render file: Rails.public_path.join("404.html"), status: 404, layout: false, content_type: 'text/html'
      }
    end
  end
  
  def internal_server
    logger.info("Exception - #{request.fullpath}")
    render_500
  end

  def unprocessable
    render status: 422
  end

end

8. app controllers concerns custom_errors.rb

# this custom error handler provide useful `send_error_notification(error)` for collecting exceptions
module CustomErrors
  extend ActiveSupport::Concern

  # without config.exceptions_app = self.routes in application.rb we would need to add custom error handling here
  # included do
  #   if Rails.env.production? || Rails.env.staging?
  #     # exception handling
  #     rescue_from Exception, :with => :render_500
  #     rescue_from ActiveRecord::RecordNotFound, :with => :render_404
  #     rescue_from ActionController::RoutingError, :with => :render_404
  #     rescue_from ActionDispatch::Http::MimeNegotiation::InvalidType, :with => :render_404
  #   end
  # end

  def render_500(exception = nil)
    if exception
      send_error_notification!(exception)
      logger.info "Rendering 500 with exception: #{exception.class} - #{exception.message}\n#{exception.backtrace.join("\n")}"
    end

    if response_body.present?
      @_response_body = nil
    end

    respond_to do |format|
      format.json { render json: {success: false, status: "500", error: "Internal Server Error"}, status: 500 }

      format.all {
        render file: Rails.public_path.join("500.html"), status: 500, layout: false, content_type: 'text/html'
      }
    end
  end

  def render_404(exception = nil)
    if exception
      logger.info "Rendering 404 with exception: #{exception.class} - #{exception.message}"
      logger.info exception.backtrace.join("\n")
    end

    respond_to do |format|
      format.json { render json: {success: false, status: "404", error: "Page Not Found"}, status: 404 }

      format.all {
        render file: Rails.public_path.join("404.html"), status: 404, layout: false, content_type: 'text/html'
      }
    end
  end

  def self.raise_error_in_test?
    Rails.env.test?
  end

  def self.send_error_notification!(exception, current_user_phone: nil, extra: {})
    error_params = {
      current_user_phone: current_user_phone
    }.merge(extra)

    # send to sentry or newrelic or somewhere else

    if raise_error_in_test?
      raise exception
    end
  end

  def send_error_notification!(exception, extra: {})
    CustomErrors.send_error_notification!(exception,
      current_user_phone: current_user_phone,
      extra: extra
    )
  end
end