Еще одна статья про Rails и ELK

Есть много туториалов, которые рассказывают как хранить логи Rails приложения в ELK, большинство сводится либо к парсингу логов, либо сохранению краткой статистики запроса по UDP в logstash. В этой статье я бы хотел сосредоточиться на переносе абсолютно всех логов приложения в ELK по UDP.

Для примера поднимем Elastic stack локально через докер. Я воспользовался этим репозиторием. Перед началом нам нужно сказать logstash'у, что присылать мы ему будем json и чтобы он этот json преобразовал нам в список полей. Для этого откроем файл logstash/pipeline/logstash.conf и добавим в него следующие строки:

filter {
  json {
    source => "message"
  }
}

Затем командой docker-compose up мы развернем весь стек ELK. После того, как докер запустит контейнер, по адресу http://0.0.0.0:5601/ у нас будет доступна Kibana.

Продемонстрирую процесс интеграции с ELK на специально заготовленном стенде. Я попытался воссоздать небольшое, но реалистичное приложение, которое хранит данные в базе, имеет какое-то API, использует кеш на Redis'е, что-то обрабатывает в фоне и иногда ходит в другие сервисы по HTTP. Итак, начнем с самого начала.

Добавим несколько гемов

# Gemfile
gem 'faraday'
gem 'hiredis'
gem 'httplog'
gem 'logstash-event'
gem 'logstash-logger', github: "motoroller95/logstash-logger"
gem 'redis'
gem 'sidekiq'

Расскажу про два основных гема: logstash-event и logstash-logger. Первый добавляет так называемый event, сущность, которая будет представлять одну запись (строчку лога), второй непосредственно сам логер. В процессе эксплуатации логера мной был найден дефект, который я исправил, но т.к. проект уже не поддерживается автором я подключил его из своего репозитория (на всякий случай pull-request висит). Так же тут присутствует еще один интересный гем httplog, который будет логировать все исходящие HTTP запросы. 

Для начала у нас есть небольшая модель

# app/models/post.rb
class Post < ApplicationRecord
  # create_table :posts do |t|
  #   t.string :title
  #   t.string :content
  #   t.boolean :published, default: false, null: false
  #   t.timestamps
  # end
end

Далее я добавил пару роутов

# routes.rb
namespace :api do
  resources :posts, except: :edit do
    post :publish, on: :member
  end
  resources :external_services, only: %i[index show]
end

Контроллеры

# app/controllers/api/external_services_controller.rb
class Api::ExternalServicesController < ActionController::API
  def index
    response = Faraday.get('https://jsonplaceholder.typicode.com/posts')
    render json: JSON.parse(response.body)
  end

  def show
    response = Faraday.get("https://jsonplaceholder.typicode.com/posts/#{params[:id]}")
    render json: JSON.parse(response.body)
  end
end

# app/controllers/api/posts_controller.rb
class Api::PostsController < ActionController::API
  before_action :find_post, only: %i[edit update destroy publish]
  after_action :clear_cache, only: %i[update destroy]

  def index
    page = (params[:page] || 1).to_i - 1
    posts = Rails.cache.fetch("posts:#{page}") do
      Post.where(published: true).limit(20).offset(20 * page).as_json
    end

    render json: posts
  end

  def create
    @post = Post.create!(post_params)
    render json: @post
  end

  def show
    render json: @post
  end

  def update
    @post.update!(post_params)
    render json: @post
  end

  def destroy
    @post.destroy!
    head :ok
  end

  def publish
    PostPublishingJob.perform_later(@post.id)
    head :ok
  end

private
  def find_post
    @post = Post.find(params[:id])
  end

  def clear_cache
    Rails.cache.clear
  end

  def post_params
    params.permit(:title, :content)
  end
end

Сразу же покажу единственную background-job 

# app/jobs/post_publishing_job.rb
class PostPublishingJob < ApplicationJob
  def perform(post_id)
    Post.find(post_id).update!(published: true)

    Rails.cache.clear
  end
end

Теперь самое важное  -  настраиваем логи

# config/application.rb
require_relative 'boot'
require_relative '../lib/logging'
require 'rails/all'

Bundler.require(*Rails.groups)

module App
  class Application < Rails::Application
    logger = LogStashLogger.new(
      type: :udp,
      host: '0.0.0.0',
      port: 5000,
      sync: true,
      customize_event: ->(event) { Logging::EventTransformer::Server.call(event) }
    )

    config.logger = logger
    config.active_job.queue_adapter = :sidekiq
    config.log_tags = %i[uuid]
    config.colorize_logging = false

    HttpLog.configure do |config|
      config.enabled = true
      config.logger = logger
    end

    redis_config = { url: 'redis://127.0.0.1:6379/0', logger: logger }
    config.cache_store = :redis_cache_store, redis_config
  end
end

А теперь по порядку. Первым делом создаем логер, которому говорим, что будем слать по UDP на 0.0.0.0 по 5000 порту. Я намеренно не стал использовать пакетную отправку логов и сделал sync = true и вот почему: по протоколу UDP мы можем отправить не более 65535 байт, что с одной стороны очень много, а с другой вызывает трудности. Если в один прекрасный момент приложение попытается записать большой кусок лога (стек-трейс к примеру) и выйдет за пределы 64кб, то мы потеряем все накопленные логи, т.к. отправка в logstash упадет с ошибкой. Конечно, есть опция max_message_size которой можно ограничить размер пакета, но в таком случае мы просто потеряем часть логов. Опция customize_event позволяет добавить дополнительные данные в лог. По сути мы создали логер, который мало чем отличается от обычного, разве что пишет не в файл, а в сеть.

Далее укажем Rails использовать наш новосозданный логер, а так же попросим логировать request_id, чтобы было удобно фильтровать запросы и выключим "разукрашивание" логов. Конфигурация HttpLog довольно простая и не нуждается в пояснениях. Финальным шагов настроим cache_store и попросим логировать все запросы к кешу.

Теперь про кастомизацию эвентов: LogstashLogger позволяет добавлять пользовательские данные к эвенту. У нас будет два типа данных, в зависимости от того в каком режиме запущено приложение: либо это сервер, либо sidekiq. В обоих случаях полезно будет логировать environment, в котором сейчас запущено приложение

# lib/event_transformer.rb
class Logging::EventTransformer
  def self.call(event)
    event[:env] = Rails.env
  end
end

Затем в случае серверной части мы добавим такой код

class Logging::EventTransformer::Server < Logging::EventTransformer
  def self.call(event)
    super

    event[:service] = 'server'
    # Так же тут можно добавить что-нибудь более интересное, но поскольку это приложение очень 
    # маленькое обойдемся только сервисом. Для примера покажу как это можно сделать
    # event[:user_id] = RequestStore[:user_id]
    # event[:some_key] = some_value
  end
end

Для sidekiq будет такой сетап

class Logging::EventTransformer::Sidekiq < Logging::EventTransformer
  def self.call(event)
    super

    event[:service] = 'sidekiq'
    # Воспользуемся тем фактом, что сайдкик устанавливает много полезной информации в 
    # локальном хранилище треда
    Thread.current[:sidekiq_context]&.each { |k, v| event[k] = v }
  end
end

Однако, чтобы эвент трансформер сайдкика начал работать нужно произвести еще одну манипуляцию — сконфигурируем sidekiq-сервер:

Sidekiq.configure_server do |_config|
  Rails.logger.formatter.instance_variable_set(
    '@customize_event',
    ->(event) { Logging::EventTransformer::Sidekiq.call(event) }
  )

  Sidekiq.logger = Rails.logger
end

Тут как всегда есть два варианта: хороший, и по-простому. Я выбрал простой и немного покопавшись в исходниках LogstashLogger я нашел где он хранит блок кастомизации эвента и просто его переопределил. Если делать по хорошему, то нужно создать новый логер и настроить все библиотеки на его использование.

Собственно на этом вся настройка закончена, если немного поиграть с приложением, то можно будет увидеть логи в ELK:

Сервер:

и Sidekiq:

А так же эвент "в развертке":

На этом все, храните ваши логи удобно!