Хакаем Rails и меняем формат логов

Illustration of a person sitting on the ground against a wall while reading a tablet. The person is wearing casual clothing with orange sneakers, and the image has a pastel color scheme.

Чтобы переделать формат логов в Rails нам в первую очередь нужно понять где вообще находятся исходники фреймворка. Для этого из папки с приложением нужно выполнить команду bundle show rails, которая выведет полный путь к коду фреймворка. Как ни странно, но внутри папки с фреймворком нет кода Rails, там лишь лежит readme и папка с гайдами. Судя по всему (и мы это, впринципе, уже знали раньше) Rails разбит на отдельные гемы, которые подключаются в rails.gemspec файле.

В этих файлах хранится информация о геме (автор, версия и т.п.) и его зависимостях.

Как видно по ссылке выше, рельса напрямую зависит от 10 гемов. Так какой же из них выводит логи? Выяснить можно двумя способами:

догадаться
запустить grep по всем установленным гемам

Догадываться не очень продуктивно, попробуем использовать grep. Я исходил из предположения что где-то в коде рельсы есть строчки текста, которые можно увидеть в логах. Возьмём, например, такой лог:

Started GET "/dashboard" for 127.0.0.1 at 2014-11-18 21:56:15 +0100
Processing by Dashboard::HomeController#index as HTML

Скорее всего, мы можем попробовать найти строчку Processing by. Выходим из папки rails-4.1.7 (или какая у вас там версия рельсы) при помощи cd ../, вбиваем ls чтобы получить список папок. Убедившись, что мы в папке со всеми гемами, начнём поиск:

grep -r "Processing by" ./*

В списке результатов поиска у меня была такая строчка:

./actionpack-4.1.7/lib/action_controller/log_subscriber.rb: info "Processing by #{payload[:controller]}##{payload[:action]} as #{format}"

Кажется, это именно то, что нам нужно – гем ActionPack. grep даже вывел нам необходимую строчку. Посмотрим на метод, которому принадлежит эта строка (комментарии добавлены мной):

  def start_processing(event)
    # Проверяем, отвечает ли логгер методу info?
    return unless logger.info?

    # Получаем событие как аргумент и разбиваем его на отдельные составляющие
    payload = event.payload

    # Например, получаем из payload параметры, которые пришли в контроллер
    params = payload[:params].except(*INTERNAL_PARAMS)

    # И запрошенный формат
    format = payload[:format]
    format = format.to_s.upcase if format.is_a?(Symbol)

    # А затем выводим это в лог
    info "Processing by #{payload[:controller]}##{payload[:action]} as #{format}"
    info " Parameters: #{params.inspect}" unless params.empty?
  end

Довольно таки простой и понятный код, да? Конечно, мы не знаем кто вызывает метод start_processing и что за event он получает, но для нашей задачи (переписать формат логов) этого и не нужно. Поэтому не будем откладывать в долгий ящик и напишем свой, русифицированный и раскрашенный вариант логов.

Rails позволяет определить какое угодно количество своих обработчиков логов путём написания своих LogSubscriber. Значит, нам нужно написать наш крутой обработчик и добавить его. Обратите внимание на следующие моменты в коде log_subscriber.rb:


module ActionController

  # Наш обработчик тоже должен наследоваться от ActiveSupport::LogSubscriber
  class LogSubscriber < ActiveSupport::LogSubscriber
    INTERNAL_PARAMS = %w(controller action format _method only_path)
  end
end

# Нам нужно прикрепить наш обработчик к :action_controller.
# Описание работы attach_to выходит за пределы этой статьи
ActionController::LogSubscriber.attach_to :action_controller

Итак, напишем обработчик ActionController::FancyLogSubscriber, который будет выводить нам строчки лога зелёным цветом, показывать внутренние параметры (controller, action) и всё на русском языке.

Прежде всего необходимо добавить в Gemfile гем colored, который даст нам красивые методы для раскраски текста в терминале.

Затем создадим в приложении файл config/initializers/fancy_log_subscriber.rb. Это не самое лучшее место для кода, но так как мы занимаемся грязным monkey patching'ом, то нам можно это сделать ;-)


# Сам код обработчика логов
class FancyLogSubscriber < ActiveSupport::LogSubscriber

  def start_processing(event)
    return unless logger.info?

    payload = event.payload
    params = payload[:params]
    format = payload[:format]
    format = format.to_s.upcase if format.is_a?(Symbol)

    info "Обрабатываем контроллером #{payload[:controller]}##{payload[:action]} в формате #{format}".green
    info " Параметры у нас такие: #{params.inspect}".blue unless params.empty?
  end

end

# Прикрепляем наш LogSubscriber к :action_controller
FancyLogSubscriber.attach_to :action_controller

Перезапускаем приложение, пробуем открыть какую нибудь страницу и смотрим в логи:

Целью этой статьи было в первую очередь показать как можно быстро разобраться в том, как работают даже такие сложные штуки, как Rails. Мы рассмотрели процесс поиска кода, отвечающего за интересующий нас участок функциональности, а так же как редактирование гема под наши нужды.

Дополнительно рекомендую к прочтению отличную статью о том, как в Rails работает механизм оповещений и обработчиков событий, которые используются в том числе для логов: http://www.paperplanes.de/2012/3/14/on-notifications-logsubscribers-and-bringing-sanity-to-rails-logging.html. Ради интереса рекомендую попробовать написать LogSubscriber для ActiveRecord, который будет так же выводить логи в другом цвете и на русском языке ;-)