Structured Logging with Rails & ELK example files

elk.rb

# Copyright 2018 Marketplacer. MIT License.

require 'json'
require 'active_support/core_ext/class/attribute'
require 'active_support/log_subscriber'

module Elk
  class RequestLogSubscriber < ActiveSupport::LogSubscriber
    PAYLOAD_KEYS_TO_COPY = %i{
      controller
      action
      format
      method
      path
      status
    }.freeze

    def logger
      return @logger if @logger
      @logger ||= ActiveSupport::Logger.new(Rails.root.join('log', 'elk.json.log'))
    end

    def process_action(event)
      data = {}
      if event.payload[:params]
        # keep in mind config.filter_parameters will be removed before this
        # point is reached: no need to check for them here. We also drop
        # params we're logging elsewhere.
        data["params"] = Flattener.flatten(event.payload[:params].except("controller", "action", "format"))
      end

      if event.payload[:exception]
        data["exception.class"] = event.payload[:exception][0]
        data["exception.message"] = event.payload[:exception][1]
      end

      PAYLOAD_KEYS_TO_COPY.each do |key|
        data[key.to_s] = event.payload[key]
      end

      data.merge! location
      data.merge! layout

      headers = event.payload[:headers] || {}
      data["http_host"] = headers["HTTP_HOST"]
      data["remote_ip"] = headers["HTTP_X_REAL_IP"]
      data["agent"] = headers["HTTP_USER_AGENT"]
      data["original_path"] = headers["ORIGINAL_FULLPATH"]

      session = headers["rack.session"]
      if session
        data["user.id"] = session["warden.user.user.key"]
        data["admin.id"] = session["warden.user.admin.key"]
        data["session_id"] = session.id
      end


      data["runtime"] = truncate_duration(event.duration)
      data["db_runtime"] = truncate_duration(event.payload[:db_runtime])
      data["view_runtime"] = truncate_duration(event.payload[:view_runtime])
      data["route"] = event.payload[:controller] + "#" + event.payload[:action]

      logger.send('debug', Oj.dump(
        "rails" => data.compact,
        "@timestamp" => Time.current.iso8601
      ))
    end

    def redirect_to(event)
      Thread.current[:elk_location] = event.payload[:location]
    end

    def render_template event
      Thread.current[:elk_layout] = event.payload[:layout] if event.payload[:layout]
    end

    def truncate_duration duration
      if duration && duration > 0
        (format "%0.2f", duration).to_f
      else
        0.0
      end
    end

    class Flattener
      LENGTH_LIMIT = 128

      attr_reader :result

      # Takes a nested hash of hashes (or arrays) and flattens it into
      # a single hash of strings, nulls or arrays only. Necessary as
      # elasticsearch gets can't index both "{ list: 5 }"
      # and "{ list: { subkey: 50 }", so we need to index them as
      # "list: 5" and "list__subkey: 50" instead.

      # This is embedded here as it's engineered directly against how
      # we want to be sending params to elasticsearch - truncating
      # long strings, making all numbers strings, etc. We need to
      # ensure everything can be indexed as the "keyword" type or we
      # risk dropping log entries on the floor due to incompatiable
      # types (eg, by indexing something as an number and then trying
      # to index that same key as a string later that day).

      def self.flatten hash
        return {} if hash.blank?
        instance = new
        hash.each_pair do |k, v|
          instance.handle(k, v)
        end
        instance.result
      end

      def initialize
        @result = {}
      end

      def handle key, val
        case val
        when Hash
          val.each_pair do |h_key, h_val|
            handle("#{key}__#{h_key}", h_val)
          end
        when Array
          val.each do |v|
            handle(key, v)
          end
        when String
          add key, val
        when Numeric
          add key, val.to_s
        when Rack::Test::UploadedFile, Rack::Multipart::UploadedFile
          add key, "[FILE UPLOAD #{val.original_filename}]"
        when nil
          add key, nil
        else
          add key, val.inspect
        end
      end

      def add key, val
        if val.is_a?(String) && val.length > LENGTH_LIMIT
          val = val.truncate(LENGTH_LIMIT, omission: "... [TRUNCATED #{val.length - LENGTH_LIMIT} CHARACTERS]")
        end

        key = key.to_s
        if @result.key?(key)
          if @result[key].is_a? Array
            @result[key] += [val]
          else
            @result[key] = [@result[key], val]
          end
        else
          @result[key] = val
        end
      end
    end

    private

    def location
      l = Thread.current[:elk_location]
      if l
        Thread.current[:elk_location] = nil
        { "redirect_to" => l }
      else
        {}
      end
    end

    def layout
      l = Thread.current[:elk_layout]
      if l
        Thread.current[:elk_layout] = nil
        { "layout": l }
      else
        {}
      end
    end

    def debug event
      # UNUSED - but kept here as there's no other way to work out what's
      # going on in this event as you can't stick a binding.pry in here
      # easily.
      event.payload[:headers].each do |k, v|
        if v.is_a? String
          $stderr.puts "#{k}: #{v}"
        else
          $stderr.puts "#{k}: #{v.class}"
        end
      end
    end
  end
end

Elk::RequestLogSubscriber.attach_to :action_controller
Elk::RequestLogSubscriber.attach_to :action_view

ingest-rails-pipeline.json

{
  "rails": {
    "processors": [
      {
        "user_agent": {
          "field": "rails.agent",
          "target_field": "rails.user_agent"
        }
      },
      {
        "rename": {
          "field": "rails.agent",
          "target_field": "rails.user_agent.orig"
        }
      },
      {
        "geoip": {
          "field": "rails.remote_ip",
          "target_field": "rails.geoip"
        }
      }
    ],
    "on_failure": [
      {
        "set": {
          "field": "error",
          "value": "{{ _ingest.on_failure_message }}"
        }
      }
    ]
  }
}

logs-index-template.json

{
  "logs": {
    "order": 0,
    "index_patterns": [
      "logs-*"
    ],
    "settings": {
      "index": {
        "mapping": {
          "total_fields": {
            "limit": "10000"
          }
        },
        "refresh_interval": "5s",
        "number_of_shards": "1",
        "number_of_replicas": "0"
      }
    },
    "mappings": {
      "_default_": {
        "_all": {
          "norms": false
        },
        "_size": {
          "enabled": true
        },
        "_meta": {
          "version": "5.5.0"
        },
        "date_detection": false,
        "dynamic_templates": [
          {
            "strings_as_keyword": {
              "mapping": {
                "ignore_above": 1024,
                "type": "keyword"
              },
              "match_mapping_type": "string"
            }
          },
          {
            "rails_params_as_keyword": {
              "mapping": {
                "ignore_above": 256,
                "type": "keyword"
              },
              "path_match": "rails.params.*",
              "match_mapping_type": "string"
            }
          }
        ],
        "properties": {
          "@timestamp": {
            "type": "date"
          },
          "rails": {
            "properties": {
              "geoip": {
                "properties": {
                  "continent_name": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "country_iso_code": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "location": {
                    "type": "geo_point"
                  }
                }
              },
              "user_agent": {
                "properties": {
                  "device": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "major": {
                    "type": "long"
                  },
                  "minor": {
                    "type": "long"
                  },
                  "name": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "os": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "os_major": {
                    "type": "long"
                  },
                  "os_minor": {
                    "type": "long"
                  },
                  "os_name": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "patch": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  }
                }
              }
            }
          },
          "beat": {
            "properties": {
              "hostname": {
                "ignore_above": 1024,
                "type": "keyword"
              },
              "name": {
                "ignore_above": 1024,
                "type": "keyword"
              },
              "version": {
                "ignore_above": 1024,
                "type": "keyword"
              }
            }
          },
          "error": {
            "ignore_above": 1024,
            "type": "keyword"
          },
          "fileset": {
            "properties": {
              "module": {
                "ignore_above": 1024,
                "type": "keyword"
              },
              "name": {
                "ignore_above": 1024,
                "type": "keyword"
              }
            }
          },
          "input_type": {
            "ignore_above": 1024,
            "type": "keyword"
          },
          "message": {
            "norms": false,
            "type": "text"
          },
          "meta": {
            "properties": {
              "cloud": {
                "properties": {
                  "availability_zone": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "instance_id": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "machine_type": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "project_id": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "provider": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "region": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  }
                }
              }
            }
          },
          "nginx": {
            "properties": {
              "access": {
                "properties": {
                  "agent": {
                    "norms": false,
                    "type": "text"
                  },
                  "body_sent": {
                    "properties": {
                      "bytes": {
                        "type": "long"
                      }
                    }
                  },
                  "geoip": {
                    "properties": {
                      "continent_name": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "country_iso_code": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "location": {
                        "type": "geo_point"
                      }
                    }
                  },
                  "http_version": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "method": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "referrer": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "remote_ip": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "response_code": {
                    "type": "long"
                  },
                  "url": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "user_agent": {
                    "properties": {
                      "device": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "major": {
                        "type": "long"
                      },
                      "minor": {
                        "type": "long"
                      },
                      "name": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "os": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "os_major": {
                        "type": "long"
                      },
                      "os_minor": {
                        "type": "long"
                      },
                      "os_name": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      },
                      "patch": {
                        "ignore_above": 1024,
                        "type": "keyword"
                      }
                    }
                  },
                  "user_name": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  }
                }
              },
              "error": {
                "properties": {
                  "connection_id": {
                    "type": "long"
                  },
                  "level": {
                    "ignore_above": 1024,
                    "type": "keyword"
                  },
                  "message": {
                    "norms": false,
                    "type": "text"
                  },
                  "pid": {
                    "type": "long"
                  },
                  "tid": {
                    "type": "long"
                  }
                }
              }
            }
          },
          "offset": {
            "type": "long"
          },
          "read_timestamp": {
            "ignore_above": 1024,
            "type": "keyword"
          },
          "source": {
            "ignore_above": 1024,
            "type": "keyword"
          },
          "tags": {
            "ignore_above": 1024,
            "type": "keyword"
          },
          "type": {
            "ignore_above": 1024,
            "type": "keyword"
          }
        }
      }
    },
    "aliases": {}
  }
}