Презентация

Трассировка событий при
логировании
Попов Александр(@alexgpg), CTI(cti.ru)
Зачем мы пишем логи?
• Отладка.
• Пишем прошедшие события. Кроме логов ничего нет. Если чтото не записали, то новой информации уже не будет.
Проблемы анализа логов
• Смешивание разных событий в одном логе.
• В распределенной системе одно событие обрабатывается на
нескольких машинах и записи об одном событии попадают в
разные логи.
• Для анализа логов нужно постоянно держать в голове контекст.
Постоянно перемещаться между исходным кодом и логами.
Антипаттерны логирования
1. Записи-близнецы
• Не понять как различить и к чему относятся. Приходится
понимать по косвенным признакам, по дополнительной
информации.
2014-06-14 01:19:06 INFO: Request to API: user: [email protected]
2014-06-14 01:19:06 INFO: Request to API: user: [email protected]
2014-06-14 01:19:06 INFO: Request to API: user: [email protected]
Антипаттерны логирования
2. Анонимный лог
• Запись в логе в которой нет имени подсистемы.
• Кто написал?
• Доходит до ctrl+c ctrl+f по исходному коду, чтобы понять что
это за подсистема
Антипаттерны логирования
3. Отсутствие цели
• Error request to api.something.com with code 500.
• А что хотели-то?
Антипаттерны логирования
4. Литературные логи
• Request from server1.api.com from user ad12 with product id 18
• Текст не поискать по приложению
• В отдельные нужные данные еще прицелится надо
Антипаттерны логирования
5. Забытый отладочный вывод
• puts user => logger.info user => logger.info «user: #{user}»
Антипаттерны логирования
6. Object.inspect
• Одновременно нечитаем человеком и машиной.
#<User:0x00000001240990 @created_at=2014-06-13 23:13:01 +0400,
@name="Petr", @organization=#<Organization:0x00000001240a08
@name="umbrella", @billing_id="122233">, @email="[email protected]",
@external_id="5757585">
Антипаттерны логирования
7. Exception без стектрейса
• Error Timeout reached.
• Ээээ...а где оно возникло и где обработалось?
Трассировка событий
• Способ пометить всю цепочку сообщений одного события,
чтобы отличать от остальных.
• В начале обработки события генерируется уникальный ID и
записывается в каждом сообщении в лог.
• Этот ID передается через все обработчики, все слои
приложения и машины участвующие в обработке.
Трассировка событий
Трассировка событий
В коде(log4r)
• Используем Nested Diagnostic Context (NDC)
# Logging init
logger = Log4r::Logger.new 'common'
outputer = Log4r::Outputter.stdout
outputer.formatter = Log4r::PatternFormatter.new(pattern: '%d %l: [%x] %m ')
logger.add outputer
# New request
Log4r::NDC.push uuid()
logger.info 'Incoming request'
#...
logger.info 'In progress'
#...
logger.error 'Bad params
Трассировка событий
В коде(ext_logging)
ev = UserEvent.new
ext_logger.info ev, 'Incoming request'
ext_logger.info ev, 'In progress'
ext_logger.error ev, 'Bad params'
Трассировка событий
В логе
2014-06-13 21:43:50 INFO: [9cc6fdc1] Incoming request
2014-06-13 21:43:50 INFO: [afc8ba03] In progress
2014-06-13 21:43:50 INFO: [9cc6fdc1] In progress
2014-06-13 21:43:50 ERROR: [9cc6fdc1] Bad params
Трассировка событий
Генерация ID события
• Искусственная — просто генерируем новый уникальный ID.
• Естественная — берем ID уже существующий в бизнес-логике.
Например, ID транзакции из внешней системы.
Трассировка событий
Иерархическая структура событий
• Обработка события может состоять из нескольких подзадач.
• Интересно наблюдать каждую из подзадач раздельно и
различать события в них друг от друга.
• При этом есть главное инициирующее событие — корень дерева
событий.
Трассировка событий
Что еще записать в лог
• Короткое имя события(reg_user, create_conf). Тогда из записи
будет понятна конечная цель
• Пользователя-инициатора события. Логин, email, ip.
• Подсистему или класс.
I, [2014-06-04T03:48:09.422777 #17400] INFO -- : [b9f64570] (add_resource){[email protected]}
<ResourcesService> | Add limit |=> {"company":"umbrella", "limit":"12"}
Трассировка событий
Преимущества
• Разные события различимы.
• Много контекста пишется сразу.
• grep позволяет фильтровать по различным признакам.
I, [2014-06-04T03:48:09.422777 #17400] INFO -- : [b9f64570] (add_resource){[email protected]}
<ResourcesService> | Add limit |=> {"company":"umbrella", "limit":"12"}
Хранимые события
• Хранятся в базе.
• Поиск средствами БД по множеству параметров(SQL, MongoDB
query).
• Можно показывать прямо в интерфейсе приложения.
• Перезапуск обработки события в случае неудачи.
Хранимые события
Схема БД
•
•
•
•
•
•
Уникальный ID
Короткое имя
Инициатор: ID или имя пользователя
Время создания
Статус: IN_POGRESS, DONE, FAILED
Дополнительные данные в свободном формате(json, hstore)
Хранимые события
Трассировка событий в логах
• Используем ID сохраненного события как ID для трассировки.
ext_logging
•
Гем для поддержки трассировки событий в логах.
•
Трассировка событий.
•
Иерархия событий.
•
Пишет класс откуда был вызван логер.
• https://bitbucket.org/alexgpg/ext_logging
• Пока в разработке.
Что почитать или посмотреть?
•
•
•
•
Nail B. Harrison «Patterns for Logging Diagnostic Messages»
Zipkin - distributed tracing system http://twitter.github.io/zipkin/
http://www.infoq.com/presentations/Zipkin
ddima Дядя Дима - Логи
ddima.livejournal.com/64901.html - часть первая
ddima.livejournal.com/65086.html - часть вторая
ddima.livejournal.com/65668.html - часть третья
ddima.livejournal.com/66497.html - часть четвертая
Выводы
• Трассировка событий — простой полезный паттерн, который
экономит время анализа логов.
• События можно хранить в БД. Это дает возможности для
гибкого задания параметров поиска по ним.
Спасибо
Вопросы?

Download Report