Статьи

Хранение ваших журналов от превращения в нечитаемый беспорядок

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

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

Пометка сообщений в журнале

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

1
2
3
Finding people...
  Person Load (0.3ms)  SELECT "people".* FROM "people"
Found 0 people!

Вы можете пометить регистратор Rails:

1
2
3
4
5
logger.tagged("People") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

И вы увидите что-то вроде этого:

1
2
3
[People] Finding people...
[People]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[People] Found 0 people!

Теперь сообщения журнала, которые заботятся о разных вещах, могут выглядеть по- разному.

Некоторые примеры Tagged Logger

По мере того, как вы будете регистрировать чаще и регистрировать более сложные вещи, вы, естественно, заметите области, в которых эти теги сделают ваши сообщения более четкими. Но есть несколько мест, которые я считаю помеченными журналирования особенно полезными. Я обычно помечаю их сразу.

Вы можете регистрировать запросы, которые вы делаете к другим API:

1
2
3
4
5
6
7
logger.tagged("GitHub API") do
 
  logger.info { "Fetching #{uri}" }
  tags = JSON.parse(Net::HTTP.get(uri))
  logger.info { "First tag: #{tags.first["name"]}" }
end
1
2
[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags
[GitHub API] First tag: v4.2.4.rc1

Таким образом, вы можете легко увидеть, как и когда ваше приложение взаимодействует с этим API. (Это особенно хорошо работает с промежуточным ПО Фарадея или если вы общаетесь только с сервером через шлюз ).

Фоновые задания также хорошо работают с тегами:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
require "active_support/tagged_logging"
 
Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger)
 
module LoggedJob
  def around_perform_log_job(*args)
    logger.tagged(name) do
      logger.info { "Performing #{name} with #{args.inspect}" }
      yield
    end
  end
end
 
class MyJob
  extend LoggedJob
 
  def self.perform(*args)
    ...
  end
end

Теперь любая работа, которая расширяет LoggedJob, будет иметь все свои сообщения журнала, помеченные именем класса работы.

И если у вас есть вошедший в систему пользователь, вы можете пометить сообщения с их идентификатором пользователя:

1
2
3
4
5
logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end
1
2
3
[user-123] Finding people...
[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[user-123] Found 0 people!

Наконец, если вы добавите строку в ваш config/environments/production.rb (или development.rb ), вы можете сделать так, чтобы Rails автоматически помечал ваши сообщения:

1
config.log_tags = [ :subdomain, :uuid ]

log_tags перечислены теги, которые вы хотите log_tags в начале каждой записи журнала Rails. Каждый символ ссылается на метод в ActionDispatch :: Request , поэтому :uuid означает request.uuid .

Вы также можете передать Proc, который принимает объект request :

1
config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]

Но я не вижу этого очень часто.

Эти теги по умолчанию хороши: uuid может связать воедино все записи журнала, которые происходят в одном запросе, и если вы храните сессии на сервере, идентификатор сессии также полезен. С помощью этих тегов и достаточного количества сообщений вы можете проследить некоторые действительно сложные пути через ваше приложение. И обычно это то, что нужно, чтобы выяснить, как произошла неприятная ошибка.

Насколько вы используете Rails logger в своих приложениях? Вы пробовали помечать логи? Если нет, попробуйте найти место для этого. Пометка действий ваших пользователей — хорошее начало. Это поможет вам в следующий раз, когда вам придется отлаживать сумасшедшую многошаговую ошибку.

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