Журналирование

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

Давайте разберемся, как писать в журнал полезные сообщения, которые всем понравятся.

1. Что журналировать

Входящие и исходящие сообщения

Если компоненты взаимодействуют друг с другом с помощью сообщений, то нужно записывать входящие и исходящие сообщения с указанием URLов конечных точек API, параметры запросов, исходные и промежуточные IP запросов, заголовки запросов, информацию об авторе, тела запросов и ответов, бизнес-контекст, временные метки и этапы внутренней обработки.

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

Вызов сервисов и функций

При вызове сервиса или функции желательно подробнее журналировать их контекст, в основном для отладки (используйте TRACE или DEBUG). Эти журналы помогут в расследовании проблем, связанных с бизнес-логикой, особенно при отсутствии привилегий по прикреплению отладчика к приложению (например, при развёртывании в тестовое, staging или pre-prod-окружение).

Действия пользователей и бизнес-статистика

У каждого приложения есть уникальные бизнес-сценарии и пользовательские маршруты (user journey), которые дают много информации профильным специалистам. Например, не слишком ли долго выполнялась определённая транзакция, или не застревают ли пользователи на какой-то функциональности всё это очень важные данные с точки зрения пользовательского опыта. Иная информация, относящаяся к бизнесу, количество транзакций и активных пользователей, а также их этапы важна для поиска причинно-следственных связей, и даже может применяться в бизнес-анализе.

Операции с данными (журнал аудита)

По соображениям безопасности и соблюдения требований регулятора в большинстве enterprise-приложений требуется вести отдельные журналы по операциям со всей важной информацией, такой как идентификаторы доступа (пользователей и систем), точные экземпляры сервисов и использованные привилегии ролей, временные метки, запросы на данные, слепки предыдущего и нового состояния изменённых данных (diff). Журнал аудита должен фиксировать все операции с данными (доступ, импорт, экспорт и т. д.), а также CRUD-операции (создание, чтение, обновление, удаление), выполненные пользователями, иными системами и сервисами.

Системные события

К ним относится информация о поведении (запусках, остановках, перезапусках и событиях, связанных с безопасностью), переходных режимах (холодный, разогрев, горячий), межсервисному взаимодействию (handshake, статусы установки соединения подключено, отключено, переподключено, повторные попытки), идентификаторы экземпляров сервисов, активно обслуживающие API, активно прослушивающие диапазоны IP и портов, загруженные конфигурации (первоначальные загрузки и динамические обновления), общее состояние сервисов, а также всё, что поможет понять поведение системы.

Статистика производительности

Усердие прекрасная характеристика вычислительных устройств, но они могут работать не идеально. В любое время могут возникнуть проблемы с производительностью или внезапные неожиданные ухудшения обслуживания (в основном из-за необработанных ошибок и повреждённых данных). Чтобы их определить, всегда рекомендуется публиковать статистику общего состояния и производительности системы. Она может содержать информацию вроде счётчиков вызовов API (успешно обслуженных и сбойных), сетевую задержку, среднюю длительность roundtripов, потребление памяти и прочую специфическую для приложения информацию (обычно определяется бизнес-контекстом).

Угрозы и уязвимости

Раскрытие угроз и уязвимостей с помощью runtimea приложения и журнала это искусство, которым должен овладеть любой разработчик enterprise-ПО. Обычно взломы и сбои не происходят внезапно. Чаще всего есть признаки, которые сначала никто не замечает. Поэтому нужно всегда журналировать подозрительную человеческую активность (например, ошибочные попытки аутентификации и верификации с приложением всей низкоуровневой информации вроде использованных сетей, источников запросов, пользовательских ролей и привилегий), а также поведение системы (например, рост пиков в паттернах потребления ресурсов, высокую нагрузку на веб-серверы, случайные сбои сервисов). Когда вы замечаете подозрительное событие, убедитесь, что журналы содержат всю связанную с ним информацию. В идеале, чтобы это была full-stack-трассировка со значениями параметров и дополнительной информацией, полученной из контекста приложения.

2. Что не нужно журналировать

Информацию личного порядка

Почти все законы, регулирующие вопросы приватности (например, GDPR, CCPA) прямо рекомендуют разработчикам не журналировать информацию, позволяющую установить личность. Сюда относятся ФИО, ники, пол, день рождения, почтовый адрес, электронную почту, телефонные номера, номер социального страхования и номера кредитных карт.

Названия компаний и контактную информацию

Убедитесь, что вы не записываете имена компаний, информацию о сотрудниках, клиентах, поставщиках, а также контактную информацию компании и отдельных людей. Журнал никогда не должен раскрывать деловые взаимосвязи и операций с третьими сторонами. Для отслеживания конкретных транзакций используйте вместо настоящих названий идентификаторы событий, сгенерированные системой, и передавайте их другим сервисам.

Финансовые данные (банковские счета, реквизиты банковских карт, пересылаемые суммы и т. д.)

По закону все финансовые данные должны быть полностью убраны или замаскированы. Раскрытие такой информации в журналах легко может привести к серьёзному судебному иску (вплоть до уголовной ответственности). Избегайте этого всеми способами.

Пароли, ключи безопасности и секреты, токены аутентификации

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

Примечание: вам легко будет определять, какую информацию нужно скрыть от журналов, если вы добавите в каждое поле атрибут, определяющий уровень видимости (например, show, mask, hide, encrypt). Если у вас есть такой механизм, то вы сможете менять видимость полей, просто обновляя свойства в конфигурации. Это хорошее решение в тех случаях, когда нужно журналировать какую-нибудь пользовательскую информацию в небоевых окружениях, особенно для тестирования и отладки. Или можно написать парсеры, которые фильтруют журналы и обрабатывают конфиденциальные поля в соответствии с заранее прописанными для этого окружения инструкциями.

3. Лучшие методики

Знайте, когда нужно использовать тот или иной уровень журналирования

Уровень журналирования используется для обозначения серьёзности каждого элемента системы. В большинстве фреймворков для журналирования есть такие уровни:

• FATAL: очень серьёзные ошибки, которые наверняка приводят к прерыванию приложения. Обычно это заканчивается серьезными сбоями.
• ERROR: ошибки, с которыми приложение ещё может продолжить работу, но с ухудшением определённых возможностей.
• WARN: менее опасные события по сравнению с ошибками. Обычно не приводят к ухудшению возможностей или полному сбою приложения. Но это всё ещё важные события, которые необходимо расследовать.
• INFO: важные баннеры событий и информационные сообщения в поведении приложения.
• DEBUG: специфическая и подробная информация, обычно используемая в отладке. Эти журналы помогают нам путешествовать по коду.
• TRACE: самые низкоуровневые данные, вроде трассировок стека, которые содержат больше всего информации об определённом событии или контексте. Эти журналы помогают исследовать значения переменных и полные стеки ошибок.

В Linux Syslog есть и более серьёзные уровни, такие как Emergency, Alert, Critical, Error, Warning, Notice, Informational и Debug.

Вне зависимости от сложности и глубины каждого уровня журналирования, мы должны корректно настраивать их в своём коде, чтобы предоставлять оптимальное количество информации в каждом сценарии. Например, все данные, используемые разработчиками для отладки и технического анализа, должны идти на уровнях DEBUG или TRACE, а баннеры с системными данными опускаются ниже INFO.

Используйте английский язык

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

2020-11-11 13:52:18 DEBUG  App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG  Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG  Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG  Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG  Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG  Adapters:20 - Successfully loaded all

Добавляйте удобные для разработчиков сообщения (краткие и содержательные)

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

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

2020-11-11 13:52:27 DEBUG  Users:18 - Successfully created new user (RecordID: 5f5a0d594d17e22b848ee570)2020-11-11 13:52:27 ERROR  Users:34 - Failed to update DB (E: inactive user, RecordID: 5f5a0d594d17e22b848ee570)

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

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

2020-11-11 13:52:27 ERROR  DB:22 - Failed to write (E:ORA-01017)// ORA-01017 denotes "invalid username/password; logon denied" error message

Используйте корректные временные метки

Временные метки позволяют понять последовательность событий, они необходимы для отладки и анализа. При фиксировании времени рекомендуется использовать наиболее подробные значения (например, на уровне милли- или микросекунд), чтобы легче было определять смежные события. Также убедитесь, что временные метки стоят в начале сообщения в формате yyyy-mm-dd HH:mm:ss. Всегда указывайте часовой пояс, если не используете на сервере время по умолчанию (UTC).

// with default server time (UTC)2020-11-11 13:52:12 INFO  XYZ Integration API Manager v2.0.0// with timezone (e.g. PST - Pacific Standard Time)2020-11-11 13:52:12PST INFO  XYZ Integration API Manager v2.0.0

Указывайте источник или происхождение журнальных данных (для DEBUG, TRACE, ERROR)

Это очень полезно для чёткого определения места, которое привело к соответствующему сообщению. Некоторые фреймворки для журналирования позволяют указывать источники на самом подробном уровне (вплоть до название файлов с номерами строк), но чаще всего достаточно упоминания только класса, функции или названия файла.

2020-11-11 13:52:12 INFO  app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO  app - Loading configurations..2020-11-11 13:52:18 INFO  app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO  app  *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO  app - *** LogLevel 05 (DEBUG)2020-11-11 13:52:12 DEBUG  App:22 - Initializing Swagger UI..2020-11-11 13:52:14 DEBUG  App:28 - Generating schemata..2020-11-11 13:52:14 DEBUG  App:30 - Initializing REST services..2020-11-11 13:52:15 DEBUG  App:32 - Generating documentation..2020-11-11 13:52:18 DEBUG  App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG  Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG  Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG  Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG  Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG  Adapters:20 - Successfully loaded all2020-11-11 13:52:31 INFO  app - Started listening...

Каждый журнал должен быть уникален в рамках системы

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

2020-11-11 13:52:18 DEBUG  App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG  Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG  Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG  Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG  Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG  Adapters:20 - Successfully loaded all

Добавьте в сообщение отслеживаемый идентификатор или токен сообщения

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

[87d4s-a98d7-9a8742jsd] Request Body: { "request_id": "87d4s-a98d7-9a8742jsd", "app_id": "TX001", "option_val": "IBM", "req_type_id": "0013", "data": {...........}[87d4s-a98d7-9a8742jsd] Sending request to RefData: href="http://personeltest.ru/away/10.244.2.168:8280/v1

Указывайте соответствие идентификаторов в точках перехода

В определённых случаях, особенно при передаче события из одной системы в другую, идентификаторы меняются в соответствии с принятым в другой системе соглашением. В таких точках перехода нужно отдельным сообщением явно указывать соответствие старого и нового идентификатора, с добавлением необходимого контекста.

[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Transaction successfully added to Rabbit Queue

Указывайте идентификаторы всех экземпляров сервиса

Большинство enterprise-систем являются распределёнными вычислительными платформами, в которых присутствует много экземпляров одних и тех же сервисов с разнообразными конфигурациями приложения, ресурсами, версиями и сетевыми свойствами. Рекомендуется присвоить экземплярам идентификаторы и использовать их при межсервисном взаимодействии.

2020-11-11 13:52:12 INFO  app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO  app - Loading configurations..2020-11-11 13:52:18 INFO  app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO  app  *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO  app - *** LogLevel 05 (DEBUG)

Настройте активный уровень журналирования

Активный уровень журналирования нужно менять в зависимости от окружения развёртывания. Для production рекомендуется выводить журналы вплоть до уровня INFO. В других окружениях журналы выводятся до уровня DEBUG или TRACE, в зависимости от степени подробности, которая нужна командам разработки и эксплуатации.

// Active Log Level = DEBUG2020-11-11 13:52:12 INFO  app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO  app - Loading configurations..2020-11-11 13:52:18 INFO  app - *** InstanceID APIM_V2_I022020-11-11 13:52:18 INFO  app  *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO  app - *** LogLevel 05 (DEBUG)2020-11-11 13:52:12 DEBUG  App:22 - Initializing Swagger UI..2020-11-11 13:52:14 DEBUG  App:28 - Generating schemata..2020-11-11 13:52:14 DEBUG  App:30 - Initializing REST services..2020-11-11 13:52:15 DEBUG  App:32 - Generating documentation..2020-11-11 13:52:18 DEBUG  App:36 - Loading adapters..2020-11-11 13:52:21 DEBUG  Adapters:10 - Loading adapter docs/v12020-11-11 13:52:22 DEBUG  Adapters:16 - Loading adapter mongo/v12020-11-11 13:52:26 DEBUG  Docs:38 - docs adapter initialized2020-11-11 13:52:27 DEBUG  Mongo:38 - mongo adapter initialized2020-11-11 13:52:22 DEBUG  Adapters:20 - Successfully loaded all2020-11-11 13:52:31 INFO  app - Started listening...// Active Log Level = INFO2020-11-11 13:52:12 INFO  app - XYZ Integration API Manager v2.0.02020-11-11 13:52:15 INFO  app - Loading configurations..2020-11-11 13:52:18 INFO  app - *** InstanceID API_V2_I022020-11-11 13:52:18 INFO  app  *** BaseURL http://10.244.2.168:30002020-11-11 13:52:19 INFO  app - *** LogLevel 04 (INFO)2020-11-11 13:52:31 INFO  app - Started listening...

Предоставляйте достаточный контекст для ошибок и сбоев

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

[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Failed to validate msg body (E: Uncaught ReferenceError: missing params - option_val)[1000508] Failed Message: { "request_id": "87d4s-a98d7-9a8742jsd", "app_id": "TX001", "req_type_id": "0013", "data": {...........}}

Подтверждайте доказательствами операции с данными (не предполагайте!)

При каждой операции с данными не принимайте на веру успешность её выполнения. Всегда проверяйте конечное состояние с помощью доказательств. Например, когда вы создаёте, обновляете или удаляете запись в базе данных, она возвращает счётчик изменённых записей и саму обновлённую запись. Всегда выполняйте проверку ожидаемого счётчика или результата. Другой пример: когда вы вставляете запись в структуру данных (например, в очередь), то проверяйте, увеличился ли её размер. Предположим, в вашей системе используются конкурентные операции, но очередь их не поддерживает. Тогда вы можете терять какие-то записи, и единственный способ обнаружить такие скрытые ошибки в коде это проверка длины.

DEBUG  BatchWriter:28 - Successfully connected to DB. Trying to insert 24 accounts...DEBUG  BatchWriter:35 - Successfully inserted 24 accounts. Total DB rows affected: 24

Шифруйте или маскируйте конфиденциальные данные

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

[1000508] ***** Incoming request from 10.244.2.168:3000 *****[1000508] Origin Id: 87d4s-a98d7-9a8742jsd -> System ID: 1000508[1000508] Request Body: {user_id:XXXXXXXXXX,personal_details:{  firstName:XXXXXXXXXX,  lastName:XXXXXXXXXX,  DOB:XXXXXXXXXX,  gender:Male,  proffessional:Software Architect,  industry:IT,  SSN:XXXXXXXXXX},address_history:[  {streetAdress:Street No 1,zipcode:XXXXX,state:CA},  {streetAdress:Street No 2,zipcode:XXXXX,state:NY},    {streetAdress:Street No 2,zipcode:XXXXX,state:AL}],card_info:[  {type:amex,card_number:XXXXXXXXX,credit_limit:XXXXX},  {type:visa,card_number:XXXXXXXXX,credit_limit:XXXXX}]}

Настройте именование файлов журналов, политики ротации, размер хранилищ и процедуры резервного копирования

Если вы пишете журналы в файлы, то убедитесь, что они хранятся на отдельном диске, который никак не влияет на работающее приложение (например, можно выделить том на удалённом сервере и прикрепить его к серверу приложений). Также выясните частоту журналирования и характер увеличения файлов. Убедитесь, что у вас есть политика ротации журналов с корректными соглашениями по наименованиям (например, при создании к названию добавляется временная метка), чтобы поддерживать идеальный размер и количество файлов. Также у вас должен быть механизм резервного копирования старых журналов в безопасное место, и механизм регулярной очистки хранилищ. В зависимости от вашей отрасли можно настроить резервное копирование по времени (обычно каждые несколько месяцев или лет), с уничтожением всех предыдущих файлов в конце периода.

[ec2-user@ip-XXX-XX-X-XXX logs]$ ls..APIM_V2_I02-2020-11-20_04:38:43.logAPIM_V2_I02-2020-11-23_02:05:35.logAPIM_V2_I02-2020-11-24_04:38:17.logAPIM_V2_I02-2020-11-27_03:28:37.logAPIM_V2_I02-2020-11-27_12:06:45.log...

4. Дополнительные рекомендации

Используйте центральный агрегатор журналов

Очень распространённая практика среди разработчиков enterprise-приложений создание центрального доступного сервера или места для сбора журналов. Обычно такие агрегаторы отслеживают журналы не только приложений, но также устройств и операционных систем (например, Linux Syslog), сети, сетевых экранов, баз данных и т. д. К тому же они отделяют файлы журналов от серверов приложений и позволяют хранить журналы в более защищённых, упорядоченных и эффективных форматах более длительное время. В некоторых отраслях (например, банковской и финансовой) необходимо хранить журналы как в локальном, так и в центральном хранилище, чтобы злоумышленники не могли получить доступ к обоим местам и одновременно удалить доказательства своей деятельности. Так что избыточность данных и их несоответствие между двумя хранилищами могут помочь заметить проникновения.

Пишите парсеры и предусмотрительно отслеживайте журналы

Возможность написания парсеров и фильтров встроена в большинство инструментов для мониторинга журналов так называемая SIEM-интеграция (security information and event management). Парсеры помогают сохранять журналы в более упорядоченных форматах, а запрашивать данные становится гораздо проще и быстрее. Также правильно организованные данные можно передавать системам мониторинга и поиска аномалий для профилактического мониторинга и прогнозирования будущих событий. Эти инструменты обладают очень широкими возможностями по графическому отображению данных на основе временных последовательностей и в реальном времени.

Настройте оповещения и push-уведомления для критических инцидентов

Почти все инструменты мониторинга журналов позволяют задавать определённым уровням свои пороговые значения. Когда система достигает таких значений, инструмент заранее обнаруживает их, помогает журналировать данные и уведомляет сисадминов с помощью оповещений, API push-уведомлений (например, Slack Audit Logs API), электронных писем и т. д. Также их можно заранее настроить на инициирование автоматических процессов вроде динамического масштабирования, резервного копирования системы, переброски нагрузки и т. д. Но если вы вкладываетесь в коммерческое ПО для мониторинга журналов, внимательно его изучите, потому что такие инструменты могут быть избыточны для небольших и средних программных систем.

5. Рекомендуемые инструменты

Фреймворки для журналирования

JavaScript/TypeScript: Log4js / pino
Java: Log4j
Golang: Logrus
Serverless-функции: aws-lambda-powertools-python / Самописное

Изучение, агрегирование и мониторинг журналов

CLI-инструменты: less, vim
Облачные инструменты: Fluentd, AWS CloudWatch
SIEM-инструменты: SolarWinds, Splunk, McAfee ESM, DataDog, IBM QRadar
Прочие: ELK Stack (ElasticSearch, Logstash, Kibana, Beats), Loggly

Понимайте свою программу без ущерба для производительности

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

Python предоставляет довольно мощный и гибкий встроенный модуль logging со множеством возможностей. В этой статье я хочу поделиться восемью продвинутыми возможностями, которые будут полезны при разработке ПО.

Основы модуля logging

Прежде чем приступить к рассмотрению продвинутых возможностей, давайте убедимся, что у нас есть базовое понимание модуля logging.

Логгер

Экземпляр, который мы создаем для генерации записей, называют логгером. Он инстанциируется через logger = logging.getLogger(name). Лучшая практика это использовать name в качестве имени логгера. name включает в себя имя пакета и имя модуля. Имя будет появляться в журнальном сообщении, что поможет разработчикам быстро находить, где оно было сгенерировано.

Форматировщик и обработчик

У любого логгера есть несколько конфигураций, которые могут быть модифицированы. Более продвинутые конфигурации мы обсудим позже, а наиболее ходовые это форматировщик (прим. пер.: formatter) и обработчик (прим. пер.: handler).

Форматировщик устанавливает структуру журнального сообщения. Каждое журнальное сообщение это объект класса LogRecord с несколькими атрибутами (имя модуля один из них). Когда мы определяем форматировщик, мы можем решить, как должно выглядеть журнальное сообщение вместе с этими атрибутами и, возможно, с атрибутами, созданными нами. Стандартный форматировщик выглядит так:

серьезность ошибки:имя логгера:сообщение# например: WARNING:root:Программа стартует!

Кастомизированный форматировщик может выглядеть так:

"%(asctime)s - [%(levelname)s] -  %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"# 2020-07-26 23:37:15,374 - [INFO] -  __main__ - (main.py).main(18) - Программа стартует!

Обработчик задает целевое местонахождение журнальных сообщений. Журнальное сообщение может быть отправлено в более чем одно место. Собственно говоря, модуль logging предоставляет довольно много стандартных обработчиков. Самые популярные FileHandler, который отправляет записи в файл, и StreamHandler, который отправляет записи в потоки, такие как sys.stderr или sys.stdout. Экземпляр логгера поддерживает ноль или более обработчиков. Если никакие обработчики не определены, тогда он будет отправлять записи в sys.stderr. Если определен более чем один обработчик, тогда целевое местонахождение журнального сообщения зависит от его уровня и от уровня обработчика.

Например, у меня есть FileHandler с уровнем WARNING (прим. пер.: предупреждение) и StreamHandler с уровнем INFO (прим. пер.: информация). Если я напишу в журнал сообщение об ошибке, то оно будет отправлено как в sys.stdout, так и в файл журнала.

Например:

В этом примере мы создали main.py, package1.py, и app_logger.py. Модуль app_logger.py содержит функцию get_logger, которая возвращает экземпляр логгера. Экземпляр логгера включает в себя кастомный форматировщик и два обработчика: StreamHandler с уровнем INFO и FileHandler с уровнем WARNING. Важно установить базовый уровень в INFO или DEBUG (уровень журналирования по умолчанию WARNING), в противном случае любые записи журнала по уровню ниже, чем WARNING, будут отфильтрованы. И main.py, и package1.py, используют get_logger, чтобы создавать свои собственные логгеры.

Диаграмма Xiaoxu Gao

# app_logger.pyimport logging_log_format = f"%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"def get_file_handler():    file_handler = logging.FileHandler("x.log")    file_handler.setLevel(logging.WARNING)    file_handler.setFormatter(logging.Formatter(_log_format))    return file_handlerdef get_stream_handler():    stream_handler = logging.StreamHandler()    stream_handler.setLevel(logging.INFO)    stream_handler.setFormatter(logging.Formatter(_log_format))    return stream_handlerdef get_logger(name):    logger = logging.getLogger(name)    logger.setLevel(logging.INFO)    logger.addHandler(get_file_handler())    logger.addHandler(get_stream_handler())    return logger# package1.pyimport app_loggerlogger = app_logger.get_logger(__name__)def process(msg):    logger.info("Перед процессом")    print(msg)    logger.info("После процесса")# main.pyimport package1import app_loggerlogger = app_logger.get_logger(__name__)def main():    logger.info("Программа стартует")    package1.process(msg="сообщение")    logger.warning("Это должно появиться как в консоли, так и в файле журнала")    logger.info("Программа завершила работу")if __name__ == "__main__":    main()# 2020-07-25 21:06:06,657 - [INFO] - __main__ - (main.py).main(8) - Программа стартует# 2020-07-25 21:06:06,658 - [INFO] - package1 - (package1.py).process(7) - Перед процессом# сообщение# 2020-07-25 21:06:06,658 - [INFO] - package1 - (package1.py).process(9) - После процесса# 2020-07-25 21:06:06,658 - [WARNING] - __main__ - (main.py).main(10) - Это должно появиться как в консоли, так и в файле журнала# 2020-07-25 21:06:06,658 - [INFO] - __main__ - (main.py).main(11) - Программа завершила работу# cat x.log# 2020-07-25 21:06:06,658 - [WARNING] - __main__ - (main.py).main(10) - Это должно появиться как в консоли, так и в файле журнала

basic-logging.py

Записи с уровнем INFO отправляются как в консольный вывод (sys.stdout), так и в файл журнала, а записи с уровнем WARNING пишутся только в файл журнала. Если вы можете полностью понять, что и почему происходит в этом примере, то мы готовы приступить к более продвинутым возможностям.

1. Создавайте заданные пользователем атрибуты объектов класса LogRecord, используя класс LoggerAdapter

Как я упоминал ранее, у LogRecord есть несколько атрибутов. Разработчики могут выбрать наиболее важные атрибуты и использовать в форматировщике. Помимо того, модуль logging также предоставляет возможность добавить в LogRecord определенные пользователем атрибуты.
Один из способов сделать это использовать LoggerAdapter. Когда вы создаете адаптер, вы передаете ему экземпляр логгера и свои атрибуты (в словаре). Этот класс предоставляет тот же интерфейс, что и класс Logger, поэтому вы все еще можете вызывать методы наподобие logger.info.

Новый атрибут с фиксированным значением

Если вы хотите иметь что-то вроде атрибута с фиксированным значением в журнальном сообщении, например имя приложения, то вы можете использовать стандартный класс LoggerAdapter и получать значение атрибута при создании логгера (прим. пер.: вероятно, получать откуда-либо, чтобы затем передать конструктору). Не забывайте добавлять этот атрибут в форматировщик. Местоположение атрибута вы можете выбрать по своему усмотрению. В следующем коде я добавляю атрибут app, значение которого определяется, когда я создаю логгер.

import logginglogging.basicConfig(    level=logging.INFO,    format="%(asctime)s - [%(levelname)s] - %(app)s - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)logger = logging.LoggerAdapter(logger, {"app": "тестовое приложение"})logger.info("Программа стартует")logger.info("Программа завершила работу")# 2020-07-25 21:36:20,709 - [INFO] - тестовое приложение - __main__ - (main.py).main(8) - Программа стартует# 2020-07-25 21:36:20,709 - [INFO] - тестовое приложение - __main__ - (main.py).main(11) - Программа завершила работу

logging_adapter_fixed_value.py

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

В других ситуациях вам, возможно, понадобятся динамические атрибуты, например что-то вроде динамического идентификатора. В таком случае вы можете расширить базовый класс LoggerAdapter и создать свой собственный. Метод process() то место, где дополнительные атрибуты добавляются к журнальному сообщению. В коде ниже я добавляю динамический атрибут id, который может быть разным в каждом журнальном сообщении. В этом случае вам не нужно добавлять атрибут в форматировщик.

import loggingclass CustomAdapter(logging.LoggerAdapter):    def process(self, msg, kwargs):        my_context = kwargs.pop('id', self.extra['id'])        return '[%s] %s' % (my_context, msg), kwargslogging.basicConfig(    level=logging.INFO,    format="%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)logger = CustomAdapter(logger, {"id": None})logger.info('ID предоставлен', id='1234')logger.info('ID предоставлен', id='5678')logger.info('Отсутствует информация об ID')# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(38) - [1234] ID предоставлен# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(38) - [1234] ID предоставлен# 2020-07-25 22:21:31,568 - [INFO] - __main__ - (main.py).<module>(39) - [5678] ID предоставлен# 2020-07-25 22:21:31,568 - [INFO] - __main__ - (main.py).<module>(39) - [5678] ID предоставлен# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(39) - [None] Отсутствует информация об ID# 2020-07-25 22:12:06,715 - [INFO] - __main__ - (main.py).<module>(39) - [None] Отсутствует информация об ID

logging_adapter_dynamic_value.py

2. Создавайте определенные пользователем атрибуты объектов класса LogRecord, используя класс Filter

Другой способ добавления определенных пользователем атрибутов использование кастомного Filter. Фильтры предоставляют дополнительную логику для определения того, какие журнальные сообщения выводить. Это шаг после проверки базового уровня журналирования, но до передачи журнального сообщения обработчикам. В дополнение к определению, должно ли журнальное сообщение двигаться дальше, мы также можем вставить новые атрибуты в методе filter().

Диаграмма из официальной документации Python

В этом примере мы добавляем новый атрибут color (прим. пер.: цвет) в методе filter(), значение которого определяется на основе имени уровня в журнальном сообщении. В этом случае имя атрибута снова должно быть добавлено в форматировщик.

import loggingclass CustomFilter(logging.Filter):    COLOR = {        "DEBUG": "GREEN",        "INFO": "GREEN",        "WARNING": "YELLOW",        "ERROR": "RED",        "CRITICAL": "RED",    }    def filter(self, record):        record.color = CustomFilter.COLOR[record.levelname]        return Truelogging.basicConfig(    level=logging.DEBUG,    format="%(asctime)s - [%(levelname)s] - [%(color)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)logger.addFilter(CustomFilter())logger.debug("сообщение для отладки, цвет  зеленый")logger.info("информационное сообщение, цвет  зеленый")logger.warning("предупреждающее сообщение, цвет  желтый")logger.error("сообщение об ошибке, цвет  красный")logger.critical("сообщение о критической ошибке, цвет  красный")# 2020-07-25 22:45:17,178 - [DEBUG] - [GREEN] - __main__ - (main.py).<module>(52) - сообщение для отладки, цвет  зеленый# 2020-07-25 22:45:17,179 - [INFO] - [GREEN] - __main__ - (main.py).<module>(53) - информационное сообщение, цвет  зеленый# 2020-07-25 22:45:17,179 - [WARNING] - [YELLOW] - __main__ - (main.py).<module>(54) - предупреждающее сообщение, цвет  желтый# 2020-07-25 22:45:17,179 - [ERROR] - [RED] - __main__ - (main.py).<module>(55) - сообщение об ошибке, цвет  красный# 2020-07-25 22:45:17,179 - [CRITICAL] - [RED] - __main__ - (main.py).<module>(56) - сообщение о критической ошибке, цвет  красный

logging_filter_dynamic_attributes.py

3. Многопоточность с модулем logging

Модуль logging на самом деле реализован потокобезопасным способом, поэтому нам не нужны дополнительные усилия. Код ниже показывает, что MainThread и WorkThread разделяют один и тот же экземпляр логгера без проблемы состояния гонки. Также есть встроенный атрибут threadName для форматировщика.

import loggingimport threadinglogging.basicConfig(    level=logging.INFO,    format="%(asctime)s - [%(levelname)s] - [%(threadName)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)def worker():    for i in range(5):        logger.info(f"журнальное сообщение {i} из рабочего потока")thread = threading.Thread(target=worker)thread.start()for i in range(5):    logger.info(f"журнальное сообщение {i} из главного потока")thread.join()# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 0-ое журнальное сообщение из рабочего потока# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 1-ое журнальное сообщение из рабочего потока# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 2-ое журнальное сообщение из рабочего потока# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 3-ое журнальное сообщение из рабочего потока# 2020-07-26 15:33:21,078 - [INFO] - [Thread-1] - __main__ - (main.py).worker(62) - 4-ое журнальное сообщение из рабочего потока# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 0-ое журнальное сообщение из главного потока# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 1-ое журнальное сообщение из главного потока# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 2-ое журнальное сообщение из главного потока# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 3-ое журнальное сообщение из главного потока# 2020-07-26 15:33:21,078 - [INFO] - [MainThread] - __main__ - (main.py).<module>(69) - 4-ое журнальное сообщение из главного потока

logging_multi_threading.py

Под капотом модуль logging использует threading.RLock() практически везде. Отличия между RLock от Lock:

1. Lock может быть получен только один раз и больше не может быть получен до тех пор, пока он не будет освобожден. С другой стороны, RLock может быть получен неоднократно до своего освобождения, но он должен быть освобожден столько же раз.

   
   

2. Lock может быть освобожден любым потоком, а RLock только тем потоком, который его удерживает.

   
   

Любой обработчик, который наследуется от класса Handler, обладает методом handle(), предназначенным для генерации записей. Ниже представлен блок кода метода Handler.handle(). Как видите, обработчик получит и освободит блокировку до и после генерации записи соответственно. Метод emit() может быть реализован по-разному в разных обработчиках.

def handle(self, record):    """    При определенных условиях генерирует журнальную запись.    Генерация зависит от фильтров, которые могут быть добавлены в обработчик.    Оборачивает настоящую генерацию записи получением/освобождением    блокировки потока ввода-вывода. Возвращает значение, свидетельствующее о том, пропустил ли фильтр запись на    генерацию.    """    rv = self.filter(record)    if rv:        self.acquire()        try:            self.emit(record)        finally:            self.release()    return rv

logging_handle.py

4. Многопроцессная обработка с модулем logging QueueHandler

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

QueueHandler + процесс-потребитель

Один из вариантов использование QueueHandler. Идея заключается в том, чтобы создать экземпляр класса multiprocessing.Queue и поделить его между любым количеством процессов. В примере ниже у нас есть 2 процесса-производителя, которые отправляют записи журнала в очередь и процесс-потребитель, читающий записи из очереди и пишущий их в файл журнала.

У записей журнала в очереди будут, вероятно, разные уровни, так что в функции log_processor мы используем logger.log(record.levelno, record.msg) вместо logger.info() или logger.warning(). В конце (прим. пер.: функции main) мы отправляем сигнал, чтобы позволить процессу log_processor остановиться. Деление экземпляра очереди между множеством процессов или потоков не новшество, но модуль logging как бы помогает нам справиться с этой ситуацией.

import osfrom logging.handlers import QueueHandlerformatter = "%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s"logging.basicConfig(level=logging.INFO)def log_processor(queue):    logger = logging.getLogger(__name__)    file_handler = logging.FileHandler("a.log")    file_handler.setFormatter(logging.Formatter(formatter))    logger.addHandler(file_handler)    while True:        try:            record = queue.get()            if record is None:                break            logger.log(record.levelno, record.msg)        except Exception as e:            passdef log_producer(queue):    pid = os.getpid()    logger = logging.getLogger(__name__)    queue_handler = QueueHandler(queue)    logger.addHandler(QueueHandler(queue))    logger.info(f"уровень INFO - производитель {pid}")    logger.warning(f"уровень WARNING - производитель {pid}")def main():    queue = multiprocessing.Queue(-1)    listener = multiprocessing.Process(target=log_processor, args=(queue,))    listener.start()    workers = []    for i in range(2):        worker = multiprocessing.Process(target=log_producer, args=(queue,))        workers.append(worker)        worker.start()    for w in workers:        w.join()    queue.put_nowait(None)    listener.join()if __name__ == '__main__':    main()# >> cat a.log # 2020-07-26 18:38:10,525 - [INFO] - __mp_main__ - (main.py).log_processer(118) - уровень INFO - производитель 32242# 2020-07-26 18:38:10,525 - [WARNING] - __mp_main__ - (main.py).log_processer(118) - уровень WARNING - производитель 32242# 2020-07-26 18:38:10,530 - [INFO] - __mp_main__ - (main.py).log_processer(118) - уровень INFO - производитель 32243# 2020-07-26 18:38:10,530 - [WARNING] - __mp_main__ - (main.py).log_processer(118) - уровень WARNING - производитель 32243

logging_queue_handler.py

QueueHandler + QueueListener

В модуле logging.handlers есть особый класс с именем QueueListener. Этот класс создает экземпляр слушателя с очередью журнальных сообщений и списком обработчиков для обработки записей журнала. QueueListener может заменить процесс, который мы создали в предыдущем примере, поместив его в переменную listener. При этом будет использовано меньше кода.

def log_producer(queue):    pid = os.getpid()    logger = logging.getLogger(__name__)    logger.addHandler(QueueHandler(queue))    logger.info(f"уровень INFO - производитель {pid}")    logger.warning(f"уровень WARNING - производитель {pid}")def main():    queue = multiprocessing.Queue(-1)    file_handler = logging.FileHandler("b.log")    file_handler.setFormatter(logging.Formatter(formatter))    queue_listener = QueueListener(queue, file_handler)    queue_listener.start()    workers = []    for i in range(2):        worker = multiprocessing.Process(target=log_producer, args=(queue,))        workers.append(worker)        worker.start()    for w in workers:        w.join()    queue_listener.stop()if __name__ == '__main__':    main()# >> cat b.log # 2020-07-26 20:15:58,656 - [INFO] - __mp_main__ - (main.py).log_producer(130) - уровень INFO - производитель 34199# 2020-07-26 20:15:58,656 - [WARNING] - __mp_main__ - (main.py).log_producer(131) - уровень WARNING - производитель 34199# 2020-07-26 20:15:58,662 - [INFO] - __mp_main__ - (main.py).log_producer(130) - уровень INFO - производитель 34200# 2020-07-26 20:15:58,662 - [WARNING] - __mp_main__ - (main.py).log_producer(131) - уровень WARNING - производитель 34200

logging_queue_listener.py

SocketHandler

Другое решение, предлагаемое учебником, отправлять записи из нескольких процессов в SocketHandler и иметь отдельный процесс, который реализует сокет-сервер, читающий записи и отправляющий их в место назначения. В этих источниках есть довольно подробная реализация.

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

5. По умолчанию не генерируйте какие-либо журнальные записи библиотеки NullHandler

На данный момент мы упомянули несколько обработчиков, реализованных модулем logging.
Другой полезный встроенный обработчик NullHandler. В реализации NullHandler практически ничего нет. Тем не менее, он помогает разработчикам отделить библиотечные записи журнала от записей приложения.

Ниже приведена реализация обработчика NullHandler.

class NullHandler(Handler):    """    Этот обработчик ничего не делает. Предполагается использовать его, чтобы избежать    разового предупреждения "Для логгера XXX не найдено никаких обработчиков". Это    важно для кода библиотеки, который может содержать код для журналирования событий. Если пользователь    библиотеки не настроил конфигурацию журналирования, то может быть    создано разовое предупреждение; чтобы избежать этого, разработчику библиотеку нужно просто создать экземпляр класса    NullHandler и добавить его в логгер верхнего уровня модуля библиотеки или    пакета.    """    def handle(self, record):        """Заглушка."""    def emit(self, record):        """Заглушка."""    def createLock(self):        self.lock = None

logging_nullhandler.py

Почему нам нужно отделять записи библиотеки от записей приложения?

По словам автора модуля logging, Vinay Sajip:

Сторонняя библиотека, которая использует logging, по умолчанию не должна выбрасывать вывод журналирования, так как он может быть не нужен разработчику/пользователю приложения, которое использует библиотеку.

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

В роли разработчика библиотеки нам нужна только одна строка кода внутри init.py, чтобы добавить NullHandler. Во вложенных пакетах и модулях логгеры остаются прежними. Когда мы устанавливаем этот пакет в наше приложение через pip install, мы по умолчанию не увидим библиотечные записи журнала.

# package/# #  __init__.py#  module1.py# __init__.pyimport logginglogging.getLogger(__name__).addHandler(logging.NullHandler())# module1.pylogger = logging.getLogger(__name__)logger.info("это информационное журнальное сообщение")

logging_nullhandler_example.py

Чтобы сделать эти записи видимыми, нужно добавить обработчики в логгер библиотеки в своем приложении.

# ваше приложение logging.getLogger("package").addHandler(logging.StreamHandler())

Если библиотека не использует NullHandler, но вы хотите отключить записи из библиотеки, то можете установить logging.getLogger("package").propagate = False. Если propagate установлен в False, то записи журнала не будут передаваться обработчикам.

6. Делайте ротацию своих файлов журнала RotatingFileHandler, TimedRotatingFileHandler

RotatingFileHandler поддерживает ротацию файлов журнала, основанную на максимальном размере файла. Здесь должны быть определено два параметра: maxBytes и backupCount. Параметр maxBytes сообщает обработчику, когда делать ротацию журнала. Параметр backupCount количество файлов журнала. У каждого продолженного файла журнала есть суффикс .1, .2 в конце имени файла. Если текущее журнальное сообщение вот-вот позволит файлу журнала превысить максимальный размер, то обработчик закроет текущий файл и откроет следующий.

Вот этот пример очень похож на пример из учебника. Должно получиться 6 файлов журнала.

import loggingfrom logging.handlers import RotatingFileHandlerdef create_rotating_log(path):    logger = logging.getLogger(__name__)    logger.setLevel(logging.INFO)    handler = RotatingFileHandler(path, maxBytes=20, backupCount=5)    logger.addHandler(handler)    for i in range(100):        logger.info("Это тестовая строка-запись в журнале %s" % i)if __name__ == "__main__":    log_file = "test.log"    create_rotating_log(log_file)

logging_file_rotation.py

Другой обработчик для ротации файлов TimeRotatingFileHandler, который позволяет разработчикам создавать ротационные журналы, основываясь на истекшем времени. Условия времени включают: секунду, минуту, час, день, день недели (0=Понедельник) и полночь (журнал продлевается в полночь).

В следующем примере мы делаем ротацию файла журнала каждую секунду с пятью резервными файлами. В каждом резервном файле есть временная метка в качестве суффикса.

import loggingimport timefrom logging.handlers import TimedRotatingFileHandlerlogger = logging.getLogger(__name__)logger.setLevel(logging.INFO)handler = TimedRotatingFileHandler(    "timed_test.log", when="s", interval=1, backupCount=5)logger.addHandler(handler)for i in range(6):    logger.info(i)    time.sleep(1)

time_file_rotation.py

7. Исключения в процессе журналирования

Зачастую мы используем logger.error() или logger.exception() при обработке исключений. Но что если сам логгер генерирует исключение? Что случится с программой? Ну, зависит от обстоятельств.

Ошибка логгера обрабатывается, когда обработчик вызывает метод emit(). Это означает, что любое исключение, связанное с форматированием или записью, перехватывается обработчиком, а не поднимается. Если конкретнее, метод handleError() будет выводить трассировку в stderr, и программа продолжится. Если у вас есть кастомный обработчик, наследуемый от класса Handler, то вы можете реализовать свой собственный handleError().

def emit(self, record):    """    Генерирует запись.    Если форматировщик указан, он используется для форматирования записи.    Затем запись пишется в поток с завершающим символом переноса строки. Если    предоставлена информация об исключении, то она форматируется с использованием    traceback.print_exception и добавляется в конец потока. Если у потока    есть атрибут 'encoding', он используется для определения того, как делать    вывод в поток.    """    try:        msg = self.format(record)        stream = self.stream        # issue 35046: merged two stream.writes into one.        stream.write(msg + self.terminator)        self.flush()    except RecursionError:  # See issue 36272        raise    except Exception:        self.handleError(record)

logging_emit.py

В этом примере во втором журнальном сообщении слишком много аргументов. Поэтому в консольном выводе мы получили трассировку, и выполнение программы все еще могло быть продолжено.

import logginglogging.basicConfig(    level=logging.INFO,    format="%(asctime)s - [%(levelname)s] -  %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)logger.info("Программа стартует")logger.info("У этого сообщения %s слишком много аргументов", "msg", "other")logger.info("Программа завершила работу")# 2020-07-26 23:37:15,373 - [INFO] -  __main__ - (main.py).main(16) - Программа стартует# --- Logging error ---# Traceback (most recent call last):#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1197, in emit#     msg = self.format(record)#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1032, in format#     return fmt.format(record)#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 756, in format#     record.message = record.getMessage()#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 443, in getMessage#     msg = msg % self.args# TypeError: not all arguments converted during string formatting (прим. пер.: не все аргументы конвертированы при форматировании строки)# Call stack:#   File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 22, in <module>#     main()#   File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 17, in main#     logger.info("У этого сообщения %s слишком много аргументов", "msg", "other")# Message: 'У этого сообщения %s слишком много аргументов'# Arguments: ('msg', 'other')# 2020-07-26 23:37:15,374 - [INFO] -  __main__ - (main.py).main(18) - Программа завершила работу

logging_error_handle.py

Однако, если исключение произошло за пределами emit(), то оно может быть поднято, и программа остановится. Например, в коде ниже мы добавляем дополнительный атрибут id в logger.info без его обработки в LoggerAdapter. Эта ошибка не обработана и приводит к остановке программы.

import logginglogging.basicConfig(    level=logging.INFO,    format="%(asctime)s - [%(levelname)s] - %(app)s - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s",)logger = logging.getLogger(__name__)logger = logging.LoggerAdapter(logger, {"app": "тестовое приложение"})logger.info("Программа стартует", id="123")logger.info("Программа завершила работу")# source/main.py# Traceback (most recent call last):#   File "/Users/ie15qx/repo/compare_xml_files/source/main.py", line 10, in <module>#     logger.info("Программа стартует", id="123")#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1960, in info#     self.log(INFO, msg, *args, **kwargs)#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 2001, in log#     self.logger.log(level, msg, *args, **kwargs)#   File "/Library/Frameworks/Python.framework/Versions/3.8/lib/python3.8/logging/__init__.py", line 1637, in log#     self._log(level, msg, args, **kwargs)# TypeError: _log() got an unexpected keyword argument 'id' (прим. пер.: _log() получил непредвиденный именованный аргумент 'id')

logging_exception_raise.py

8. Три разных способа конфигурирования своего логгера

Последний пункт, которым я хотел поделиться, о конфигурировании своего логгера. Есть три способа конфигурирования логгера.

используйте код

Самый простой вариант использовать код для конфигурирования своего логгера, так же, как во всех примерах, что мы видели ранее в этой статье. Но недостаток этого варианта в том, что любая модификация (прим. пер.: конфигурации) требует внесения изменений в исходном коде.

use dictConfig

Второй вариант записывать конфигурацию в словарь и использовать logging.config.dictConfig, чтобы читать ее. Вы также можете сохранить словарь в JSON-файл и читать оттуда. Плюс в том, что этот файл может быть загружен как внешняя конфигурация, но он может способствовать появлению ошибок из-за своей структуры.

import loggingimport logging.configLOGGING_CONFIG = {    'version': 1,    'disable_existing_loggers': True,    'formatters': {        'standard': {            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'        },    },    'handlers': {        'default': {            'level': 'INFO',            'formatter': 'standard',            'class': 'logging.StreamHandler',            'stream': 'ext://sys.stdout',        },    },    'loggers': {        '': {  # root logger            'handlers': ['default'],            'level': 'DEBUG',            'propagate': True,        }    },}logging.config.dictConfig(LOGGING_CONFIG)if __name__ == "__main__":    log = logging.getLogger(__name__)    log.info("hello world")# 2020-07-28 21:44:09,966 [INFO] __main__: hello world

logging_configure_json.py

используйте fileConfig

И последний, но не менее важный, третий вариант использовать logging.config.fileConfig Конфигурация записывается в отдельный файл формата .ini.

# logging_config.ini# [loggers]# keys=root# [handlers]# keys=stream_handler# [formatters]# keys=formatter# [logger_root]# level=DEBUG# handlers=stream_handler# [handler_stream_handler]# class=StreamHandler# level=DEBUG# formatter=formatter# args=(sys.stderr,)# [formatter_formatter]# format=%(asctime)s %(name)-12s %(levelname)-8s %(message)simport loggingfrom logging.config import fileConfigfileConfig('logging_config.ini')logger = logging.getLogger()logger.debug('hello world')

logging_configure_file.py

Есть возможность обновлять конфигурацию во время выполнения программы через сервер конфигурации. Учебник показывает пример как со стороны клиента, так и со стороны сервера. Конфигурация обновляется посредством подключения через сокет, а на стороне клиента мы используем c = logging.config.listen(PORT) c.start(), чтобы получать самую новую конфигурацию.

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