Лог что это в тестировании
JUnit тесты для логирования
Логирование относится к сквозной функциональности — разбросанной по коду и, как правило, редко покрываемой юнит-тестами. Слабое покрытие тестами, очевидно, связано с тем что вывод в лог не всегда достаточно важен и воспринимается скорее как вспомогательная функция а не цель работы метода, к тому же тестировать сквозную функциональность бывает достаточно сложно.
Но когда корректность вывода в лог становится критичной или же чувство прекрасного требует от нас полного покрытия кода тестами — без тестирования логгеров становится не обойтись.
Предположим у нас есть простой класс с log4j-логгером и методом doSomethingWithInt
Мы хотим протестировать факт того что вызов метода
приведет к выводу в лог
— метод doSomethingWithInt вызван с параметром i = 1
— параметр i больше нуля
Традиционный подход к тестированию предполагает, инжектирование mock-объекта (с помощью Mockitio) в тестируемый класс и, после отработки тестируемого кода, проверку того как и какие параметры передавались в mock.
Проблема в том, что инжектировать логгер в наш класс достаточно сложно — он не передается в ClassWithLog4JLogger а возвращается из static-метода, подменять returnValue которого Mockito не умеет (и у этого есть определенные основания — Mockito предназначено для тестирования объектов, в то время как static-метод относится к классу а не объекту). Но проблема, конечно, решаема — причем несколькими способами
Способ 1. Mock для log4j-Appender-а
“За неимением горничной имеем дворника. ” Пусть мы не можем подменить сам логгер — но мы можем подсунуть ему mock-аппендер и убедиться, что логгер передает в аппеддер те события которые мы ожидаем.
Добавим проект JUnit и Mockito
и напишем вот такой тест
Все вроде бы достаточно просто и не нуждается в пояснении.
Единственный минус такого подхода — так как мы тестируем не логгер а аппендер то мы проверяем не аргументы методов логгера а аргументы которые логгер передает аппендеру (LoggingEvent-ы), а их верификация занимает чуть больше строчек кода.
Данный подход сработает и в том случае если в качестве логгера используется slf4J Это надстройка над log4j (и еще несколькими фреймворками логирования), позволяющая, например, выводить в лог параметры без конкатинации строк (см. пример ниже). Сам slf4J-логгер не имеет методов для добавления аппендера. Но при этом он в процессе работы использует нижестоящий фреймворк (из найденных в classpath). Если этим фреймворком будет log4j то мы можем подсунуть mock-аппендер в log4j-логгер — он в свою очередь будет вызван из slf4J
Итак, добавляем зависимости на slf4j и его связку с log4j
И протестируем класс почти такой же как в предыдущем примере — отличие только в логгере и передачи параметров в лог (теперь без конкатенации строк)
Тест для него останется точно таким же — изменится только название класса для которого получаем логгер (при том что это по-прежнему log4j а не slf4j логгер)!
Способ 2. Подмена slf4j-имплементации.
Но что если мы все же хотим подменить не аппендер а сам логгер? Это таки-возможно. Как уже говорилось выше — slf4 использует на выбор один из нижестоящих фреймворков (log4j, logback и т.д.) Можно добавить в проект еще одну реализацию и при этом удалить из classpath остальные — тогда slf4 “подхватит” именно ее. А в тестовой реализации логгера есть методы позволяющие проверить его вызовы.
Итак — добавляем зависимость
и — ВАЖНО(!) удаляем в процессе сборки другие slf4j-логгеры если они есть в проекте.
Тест (для класса, используемого в прошлом примере) выглядит крайне просто
Проще некуда. Но есть и минус — работать тест будет только в связке с maven-ом или другой системой сборки которая удалит классы других логгеров, при этом предыдущий тест, заточенный на slf4j-log4j не отработает. На мой взгляд это не очень удобно так как сковывает нас в используемых средствах (обязательно запуск мавеном) и инструментах (не использование в тестах других логгеров).
Способ 3. Mock-логгер при помощи PowerMock
PowerMock — это как Mockito. Но круче. Чем круче? Тем, что может работать со static-методами, финальными классами, protected и даже private полями… Эдакий молоток в ювелирной лавке (кстати, именно кувалда изображена на эмблеме PowerMock) — в повседневном использовании инструмент слишком мощный, но иногда и без него — никуда. Вот и для тестирования логирования он отлично подходит — мы просто переопределялем метод LoggerFactory.getLogger и подсовываем ему наш mock-объект,
Резюме
Все способы имеют право на существование. Мокирование аппендера представляется наиболее простым, не требующем использования новых (кроме JUnit и Mockito) библиотек, но не работает непосредственно с логгером.
Slf4j-test требует минимум кода — но заставляет играться с подменой классов в classpath. А PowerMock достаточно прост и позволяет инжектить в тестируемый класс mock-логгер.
Python: Логируем как профессионалы
Часто вижу, что помимо обработки исключений, люди мучаются кое с чем еще, а именно с логированием.
Большинство людей не знают, что писать в логи, поэтому решают логировать все, что угодно, думая, что все подряд – это в любом случае лучше, чем ничего, и, в конечном итоге, просто создают шум. А шум – это информация, которая никак не помогает вашей команде понять, в чем дело и как решить проблему.
Более того, я не думаю, что эти люди могут уверенно пользоваться уровнями логирования, поэтому используют по умолчанию logger.info везде (если не пишут print ).
Наконец, люди, похоже, не знают, как сконфигурировать логирование в Python, понятия не имеют, что такое обработчики, фильтры, методы форматирования (форматтеры) и т.д.
Цель этой статьи – разъяснить, что такое логирование и как вы должны его реализовывать. Я постараюсь привести содержательные примеры и обеспечить вас гибкими эмпирическими приемами, которые следует использовать при логировании в любом приложении, которое вы когда-либо будете создавать.
Введение
Примеры облегчают визуальное восприятие, поэтому мы будем рассматривать следующую систему:
Пользователи могут подключать несколько интеграций к ресурсам (например, GitHub, Slack, AWS и т.д.)
Ресурсы уникальны в зависимости от интеграции (например, репозитории списков с GitHub, диалоги из Slack, экземпляры списков EC2 из AWS и т.д.)
Каждая интеграция уникальна, имеет свой набор сложностей, конечных точек, шагов и т.д.
Каждая интеграция может привести к различным ошибкам, которые могут возникнуть в любое время (например, неверная аутентификация, ресурс не существует и т.д.)
Я не буду сосредотачиваться на проблемах поддержки таких интеграций, просто пронаблюдаем за тем, как это работает.
Природа логирования: хорошее логирование имеет значение
Для начала давайте проанализируем характеристики логов.
«Наглядными» мы их называем потому, что они предоставляют вам какую-то информацию, «контекстными», потому что они дают вам общее представление о том, как обстоят дела на данный момент времени. И наконец, «реактивными» они являются потому, что они позволяют вам предпринимать действия только после того, как что-то произошло (даже если ваши логи отправляются/получаются в режиме реального времени, на самом деле вы не можете изменить то, что произошло только что).
Если вы не будете учитывать природу логов, то будете производить только шум, что снизит вашу производительность.
Дальше я приведу несколько примеров, основанных на системе, которую мы определили выше:
Если вы зададите описание, к примеру «operation connect failed», но не добавите контекст, трудно будет понять, какая из интеграций не отработала, кто пострадал, на каком этапе подключения произошел сбой, поэтому и среагировать вы не можете. В конечном итоге вы будете копаться в тонне логов без малейшего представления о том, где может быть проблема.
О, а еще не стоит недооценивать способность разработчика испортить описание. Сделать это легко, просто отправив поверхностные сообщения без какого-либо контекста, например «An error happened» или «An unexpected exception was raised». Если я прочту такое, то даже не пойму, на что повлияла ошибка, потому что не буду знать, ЧТО конкретно произошло. Так что да, можно сломать даже основной смысл логов.
Логи – это конфиденциальная информация из вашего программного обеспечения, нужная чтобы вы оставались в курсе происходящего и могли реагировать на ситуации. Любые логи, которые не дают вам такой информации – это шум.
Когда нужно логировать?
Чтобы логи оставались реактивными, вам нужно логировать «события». Сделайте их такими же понятными и удобными для чтения, как эта статья. Возможно, вы не прочитали каждую строку, которую я написал выше, но вы все равно можете продолжить дальше, пропустить ненужные разделы и сосредоточиться на том, что привлекло ваше внимание. Логи должны быть такими же.
Есть эмпирическое правило построение логов:
В начале соответствующих операций или потоков (например, при подключении к сторонним сервисам и т.д.);
При любом достигнутом прогрессе (например, успешная аутентификация, получен валидный код ответа и т.д.);
При завершении операции (успешном или неудачном).
Логи должны рассказывать вам историю, у каждой истории есть начало, середина и конец.
Будьте осторожны с релевантностью, добавлять логи проще, чем удалять их, ведь все, что нерелевантно – шум.
Что логировать?
Чтобы логи были наглядными и контекстными, нужно предоставлять правильный набор информации, и я не могу сказать, какая информация будет являться таковой, не зная вашего случая. Давайте вместо этого воспользуемся нашим примером.
Рассмотрим интеграцию с AWS в качестве примера. Было бы круто иметь следующие сообщения:
Хороший пример логов
Сообщение
Понимание картины
Контекст
Началась операция с AWS
Атрибуты лога должны позволить мне выяснить, кто его вызвал
Retrieved instances from all regions
Был достигнут существенный прогресс
Connection to AWS has been successful
Операция с AWS завершилась
Атрибуты лога должны позволить мне найти сущности, на которые операция произвела положительный эффект
Пример логов об ошибках
Допустим, что извлечь экземпляры из региона af-south-1 не удалось из-за какой-то внезапной ошибки в этом регионе.
Сообщение
Понимание картины
Контекст
Началась операция с AWS
Атрибуты лога должны позволить мне выяснить, кто его вызвал
Failed to retrieve instances from regions af-south-1 when connecting to AWS for user X
Операция AWS не завершена, произошел сбой в регионе af-south-1, пострадал пользователь X
Я должен иметь возможность увидеть трассировку стека ошибки, чтобы понять, почему извлечение не удалось
В обоих случаях, я могу отследить, когда произошло какое-то событие (в логах есть отметки о времени), что именно произошло и кто от этого пострадал.
Я решил не указывать пользователя при начале и успешном завершении операции, потому что это не имеет значения (ведь это шум), поскольку:
Если я знаю, что что-то запустилось, но не знаю результата выполнения, то что я могу сделать?
Если все хорошо, то зачем беспокоиться?
Добавление таких данных делает логи шумными, потому что на них невозможно реагировать, делать-то с этим ничего не надо! Но я все еще должен быть в состоянии собрать детальную информацию из атрибутов (кто, когда, почему и т.д.). Если вы хотите что-то измерить, вам следует воспользоваться метриками, а не логами.
С другой стороны, логи об ошибках кажутся более подробными, и так и должно быть! Чтение таких логов дает достаточно уверенности, чтобы немедленно перейти к действиям:
Свяжитесь с пользователем Х и сообщите ему, что вам известно о проблеме в этом регионе.
Ключевой момент следующий: вы можете отреагировать сразу и для этого вам не требуется более глубокого изучения ситуации. Вы знаете все, что вам нужно, и можете немедленно принять меры для уменьшения ущерба. Разработчикам, возможно, потребуется углубиться в трассировку стека, чтобы собрать больше контекста (в случае с ошибкой), но общая картина уже становится ясна.
Любое сообщение об ошибке, в котором отсутствует эта минимальная информация, становится шумом, поскольку у вас появляется беспокойство, но вы все еще не можете действовать. Сначала нужно углубиться в ситуацию, чтобы понять, насколько проблема серьезна.
Если вы все еще не поняли, как писать полезные сообщения, я поделюсь с вами очень простым лайфхаком:
Всегда спрашивайте себя: Что я хочу уяснить для себя, после получения такого лога?
Предоставление контекста с помощью Python
В Python атрибуты логов можно добавить с помощью дополнительного поля, например:
Контекст не отменяет необходимости в содержательных сообщениях! Поэтому я бы так не делал:
Сообщения должны быть четкими и не оставлять места вопросам о том, что же вообще происходит. Контекст должен обогащать ваш опыт, предоставив информацию о более глубоких деталях, и давать вам понимание, по какой причине что-то произошло.
Нечто большее, чем logger.info и logger.error
Не так-то просто понять, что происходит, когда тысячи клиентов выдают логи «Connecting to Slack». Поскольку вы выдаете логи, а вашим приложением пользуются несколько клиентов, нужно иметь возможность фильтровать информацию по релевантности.
Чтобы упростить ситуацию, вот вам новое эмпирическое правило (будьте гибкими):
Уровень
Когда используется
Для какой-то действительно повторяющейся информации. Возможно, было бы полезно выдавать весь контекст информации, но порой этого не нужно.
Когда происходит что-то важное, достойное того, чтобы о нем было известно большую часть времени.
Случилось что-то странное (но не прервало поток/операцию). Если проблема возникнет на более поздних этапах, такой лог может дать вам подсказку.
Произошла ошибка, ее следует устранить как можно быстрее.
Произошла очень серьезная ошибка, она требует немедленного вмешательства. Если не уверены в критичности ошибки, применяйте ERROR .
Для описанной системы/потоков, я бы использовал уровни логов, как определено:
Что делать с logger.critical и logger.warning ?
WARNING – недостаточно веская причина для остановки потока, однако это предупреждение на будущее, если возникнет какая-то проблема.
CRITICAL – самый тревожный предупреждающий лог, который вы когда-либо получите. По сути, он должен быть той самой причиной встать в три часа ночи и пойти что-то чинить.
Для этих случаев мы рассмотрим:
Для AWS: если какой-то регион AWS недоступен, мы можем предположить, что у пользователя там нет никаких ресурсов, поэтому можно двигаться дальше.
Для Slack: если OAuth завершится неудачно из-за невалидного id клиента, значит остальные пользователи столкнутся с той же проблемой, интеграция не отработает, пока мы вручную не сгенерируем новый id. Это дело кажется достаточно критичным.
Непопулярное мнение: использование DEBUG -уровня на продакшене
Да, я считаю, что логи DEBUG нужно использовать на продакшене.
Другой вариант – включить дебаг после того, как странная ошибка потребует более детального разбирательства.
Простите, но для меня такой вариант недопустим.
В реальном мире клиентам нужна быстрая реакция, командам нужно выполнять свою работу и постоянно поддерживать системы в рабочем состоянии. У меня нет времени и пропускной способности для нового деплоя или включения флага и ожидания повторения проблемы. Я должен реагировать на неожиданные проблемы в считанные секунды, а не минуты.
Правильно настройте логгер
Еще я замечаю, что люди испытывают трудности при настройке логгера (или вообще его не настраивают). Конечно, документация в Python не очень дружелюбная, но это не оправдание, чтобы вообще ее не трогать.
Использование ручных команд непросто поддерживать и понимать;
fileConfig – негибкая история, у вас не бывает динамических значений (без дополнительных фокусов);
dictConfig – простая история в запуске и настройке.
Я поделюсь несколькими советами и определениями, которые вам надо знать, а затем мы создадим окончательную конфигурацию на реальных примерах из проектов, над которыми я работаю.
Вот кусочек того, о чем мы будем говорить дальше:
Что такое логгеры?
В любом случае, придерживайтесь:
Форматируйте логи
Форматтеры вызываются для вывода конечного сообщения и отвечают за него преобразование в конечную строку.
Когда я работал в Zak (бывшем Mimic), и даже сегодня в Lumos мы форматировали логи как JSON. Он является хорошим стандартом для систем, работающих на продакшене, поскольку содержит множество атрибутов. Проще визуализировать JSON, чем обычную длинную строку, и для этого вам не нужно создавать свой собственный форматтер (ознакомьтесь с python-json-logger).
Для локальной разработки я рекомендую использовать форматирование по умолчанию для простоты.
Ваше решение будет зависеть от вида проекта. Для Tryceratops я решил использовать обычный форматтер, поскольку он проще и работает локально, там нет нужды в JSON.
Фильтруйте логи
Фильтры можно использовать либо для фильтрации логов (внезапно), либо для добавления дополнительного контекста в запись лога. Рассматривайте фильтры, как хуки, вызываемые до обработки итогового лога.
Их можно определить следующим образом:
Или их можно добавить прямо в логгер или обработчик для упрощения фильтрации по уровням (скоро будут примеры).
Обрабатывайте логи и то, как все связано
Обработчики представляют из себя комбинации форматтеров, выходных данных (потоков) и фильтров.
С ними вы можете создавать следующие комбинации:
Выводить все логи из info (фильтр), а потом выводить JSON в консоль.
Выводить все логи, начиная с error (фильтр) в файл, содержащий только сообщение и трассировку стека (форматтер).
Наконец логгеры указывают обработчикам.
Пример logging.dictConfig
Теперь, когда вы понимаете, что делают все эти объекты, давайте писать собственные! Как всегда, я постараюсь показать вам примеры из реальной жизни. Я буду использовать конфигурацию Tryceratops. Вы можете открыть ссылку и посмотреть самостоятельно окончательную конфигурацию.
Шаблон конфигурации логирования
Начнем с такого каркаса, создадим константу LOGGING_CONFIG :
Version всегда будет 1. Это плейсхолдер для возможных следующих релизов. На данный момент версия всего одна.
Я рекомендую оставить значение disable_existing_loggers в False, чтобы ваша система не поглощала другие неожиданные проблемы, которые могут возникнуть. Если вы хотите изменить другие логгеры, я бы порекомендовал их явно переписать (хоть это и скучно).
Корневой логгер можно определить тремя разными способами, что сбивает с толку:
Выбирайте любой! Мне нравится оставлять его снаружи, поскольку так он выглядит очевиднее и подробнее говорит о том, чего я хочу, ведь корневой логгер влияет на все другие определенные логгеры.
Конфигурация логирования: форматтеры
Я дополню пример из Tryceratops примером с JSON из Lumos.
Конфигурация логирования: обработчики
Конфигурация логирования: логгеры и root
Давайте разберемся, что происходит:
Кроме того, обратите внимание, что я могу переписать правила по умолчанию. Через настройки или позже динамически. Например, каждый раз, когда triceratops получает подобный флаг от CLI, он обновляет конфигурацию logging чтобы включить дебаг.
Логирование – это важно, но наличие хорошо структурированных исключений и блоков try/except также важно, поэтому вы можете также прочитать, как профессионально обрабатывать и структурировать исключения в Python.
Всех желающих приглашаем на demo-занятие «Основы ООП». Цели занятия: научиться работать с классами и познакомиться с наследованием.
Краткое содержание:
— мутабельность экземпляров класса
— передача аргументов в инициализатор
— наследование
— переопределение методов
— обращение к методам суперкласса
>> РЕГИСТРАЦИЯ
Логирование как инструмент повышения стабильности веб-приложения
техлид в Dunice
Каждый проект так или иначе имеет жизненные циклы: планирование, разработка MVP, тестирование, доработка функциональности и поддержка. Скорость роста проектов может отличаться, но при этом желание не сбавлять обороты и двигаться только вперёд у всех одинаковые. Перед нами встаёт вопрос: как при работе над крупным проектом минимизировать время на выявление, отладку и устранение ошибок и при этом не потерять в качество?
Существует много различных инструментов для повышения стабильности проекта:
В данной статье я хочу поговорить об одном из таких инструментов — логировании.
Логи — это файлы, содержащие системную информацию о работе сервера или любой другой программы, в которые вносятся определённые действия пользователя или программы.
Логи полезны для отладки различных частей приложения, а также для сбора и анализа информации о работе системы с целью выявления ошибок. Всё это необходимо для контроля работы приложения, так как даже после релиза могут встретиться ошибки, а пользователи не всегда сообщают о багах в техподдержку. Чем больше процессов у вас автоматизировано, тем быстрее будет идти разработка.
Допустим, есть клиентское приложение, балансировщик в лице Nginx, серверное приложение и база данных.
В данном примере не важны язык/фреймворк бэкенда, фронтенда или тип базы данных, а вот про веб-сервер Nginx давайте поговорим. В данный момент Nginx популярнее остальных решений для высоконагруженных сайтов. Среди известных проектов, использующих Nginx: Рамблер, Яндекс, ВКонтакте, Facebook, Netflix, Instagram, Mail.ru и многие другие. Nginx записывает логи по умолчанию, без каких-либо дополнительных настроек.
Логи доступны 2 типов:
Клиент отправляет запрос на сервер, и в данной ситуации Nginx будет записывать все входящие запросы. Если возникнут ошибки при обработке запросов, сервером будет записана ошибка.
2020/04/10 13:20:49 [error] 4891#4891: *25197 connect() failed (111: Connection refused) while connecting to upstream, client: 5.139.64.242, server: app.dunice-testing.com, request: «GET /api/v1/users/levels HTTP/2.0», upstream: «http://127.0.0.1:5000/api/v1/users/levels», host: «app.dunice-testing.com»
Всё, что мы смогли бы узнать в случае возникновения ошибки, — это лишь факт наличия таковой, не более. Это полезная информация, но мы пойдём дальше. В данной ситуации помог Nginx и его настройки по умолчанию. Но что же нужно сделать, чтобы решить проблему раз и навсегда? Необходимо настроить логирование на сервере, так как он является общей точкой для всех клиентов и имеет доступ к базе данных.
Первым делом каждый запрос должен получать свой уникальный идентификатор, что поможет отличить его от других запросов. Для этого используем UUID/v4. На случай возникновения ошибки, каждый обработчик запроса на сервере должен иметь обёртку, которая отловит эти самые ошибки. В этой ситуации может помочь конструкция try/catch, реализация которой есть в большинстве языков.
В конце каждого запроса должен сохраняться лог об успешной обработке запроса или, если произошла ошибка, сервер должен обработать её и записать следующие данные: ID запроса, все заголовки, тело запроса, параметры запроса, отметку времени и информацию об ошибке (имя, сообщение, трассировка стека).
Собранная информация даст не только понимание, где произошла ошибка, но и возможную причину её возникновения. Обычно для решения ошибки информации из лога достаточно, но в некоторых случаях может быть полезен контекст запроса. Для этого необходимо при старте запроса не только генерировать ID запроса, но и сгенерировать контекст, в который мы будем записывать всю информацию по работе сервера, начиная от результата вызова функции и заканчивая результатом запроса к базе данных. Такая реализация даст не только входные данные, но и промежуточные результаты работы сервера, что позволит понять причину появления ошибки.
При микросервисном подходе система не ограничивается одним сервером, и при запросе от клиента происходит взаимодействие нескольких серверов внутри системы. Наша реализация логирования на сервере позволит выявить дефект в работе конкретного ресурса, но не позволит понять, почему запрос вернулся с ошибкой. В данной ситуации поможет трассировка запросов.
Трассировка — процесс пошагового выполнения программы. В режиме трассировки программист видит последовательность выполнения команд и значения переменных на каждом шаге выполнения программы.
В нашем случае требуется передавать метаинформацию о запросе при взаимодействии серверов и записывать логи в единое хранилище (такими могут быть ClickHouse, Apache Cassandra или MongoDB). Такой подход позволит привязать различные контексты серверов к уникальному идентификатору запроса, а отметки времени — понять последовательность и последнюю выполненную операцию. После этого команда разработки сможет приступить к устранению.
В некоторых случаях, которые встречаются крайне редко, к ошибке приводят неочевидные факторы: компилятор, ядро операционной системы, конфигурации сервера, юзабилити, сеть. В таких случаях при возникновении ошибки потребуется дополнительно сохранять переменные окружения, слепок оперативной памяти и дамп базы. Такие случаи настолько редки, что не стоит беспочвенно акцентировать на них внимание.
С сервером разобрались, что же делать, если у нас сбои даёт клиент и запросы просто не приходят? В такой ситуации нам помогут логи на стороне клиента. Все обработчики должны отправлять информацию на сервер с пометкой, что ошибка с клиента, а также общие сведения: версия и тип браузера, тип устройства и версия операционной системы. Данная информация позволит понять, какой участок кода дал сбой и в каком окружении пользователь взаимодействовал с информацией.
Также есть возможность отправлять уведомления на почту разработчикам, если произошли ошибки, что позволит оперативно узнавать о сбоях в системе. Такие подходы активно используются в системах мониторинга и аналитики логов.
Способы, которые мы рассмотрели в статье, помогут следить за качеством продукта и минимизируют затраты на исправление недочётов в системе.