Распределенное логирование и трассировка для микросервисов
Содержание:
Популярные ошибки в логировании
- Избыток логирования. Не стоит логировать каждый шаг, который чисто теоретически может быть важным. Есть правило: логи могут нагружать работоспособность не более, чем на 10%. Иначе будут проблемы с производительностью.
- Логирование всех данных в один файл. Это приведет к тому, что в определенный момент чтение/запись в него будет очень сложной, не говоря о том, что есть ограничения по размеру файлов в определенных системах.
- Использование неверных уровней логирования. У каждого уровня логирования есть четкие границы, и их стоит соблюдать. Если граница расплывчатая, можно договориться какой из уровней использовать.
Dictionary Schema — Detail
The dictionary passed to dictConfig() must contain the following
keys:
version — to be set to an integer value representing the schema
version. The only valid value at present is 1, but having this key
allows the schema to evolve while still preserving backwards
compatibility.
All other keys are optional, but if present they will be interpreted
as described below. In all cases below where a ‘configuring dict’ is
mentioned, it will be checked for the special '()' key to see if a
custom instantiation is required. If so, the mechanism described
above is used to instantiate; otherwise, the context is used to
determine how to instantiate.
External Services
For some more serious enterprise level projects, implementing your own logging
systems may not be sufficient and you may have to interface with external
logging services such as LogStash. These services do the job of collecting,
parsing and transforming the logged output of your application for you.
You may wonder what the point of this is, but as we move towards more
micro-service based solutions, the storing of log files everywhere and searching
through them when things go wrong is just not feasible. Imagine you had 10
instances of a service deployed on 10 distinct servers. Having to work through
all 10 of these log files would be a nightmare should you encounter an issue.
The only real solution is to have the instances of your service output your logs
to something such as Logstash so that you can far more easily trawl through an
aggregated view of your logs.
Python and Logstash
I’d recommend that if you go down this approach then you look at projects such
as vklochan/python-logstash which
very easily allows you to integrate Logstash with your Python applications.
Практические советы
Модуль журналирования весьма полезен, однако некоторые его особенности могут вызвать головную боль даже у опытных разработчиков. Есть несколько практических советов по применению этого модуля.
Настроить корневой диспетчер, но не использовать его в коде, к примеру, никогда не вызывать функцию , которая скрыто обращается к корневому диспетчеру. Если вы хотите отловить сообщения об ошибках из используемых библиотек, настройте этот диспетчер, например, на запись в файл, чтобы облегчить отладку. По умолчанию сообщения выводятся только в , поэтому журнал легко потерять.
Для использования журналирования создайте новый диспетчер с помощью
Обратите внимание на валидность имени. Чтобы добавить обработчики, можно использовать метод, возвращающий диспетчер.
После этого можно создать и использовать новый диспетчер:
- Используйте классы RotatingFileHandler, например так, как применён TimedRotatingFileHandler в приведённом выше примере вместо FileHandler. Благодаря этому смена файла журнала будет происходить автоматически при достижении максимального размера или по расписанию.
- Для автоматического отслеживания сообщений об ошибках используйте такие инструменты, как Sentry, Airbrake, Raygun и тому подобные. Особенно это полезно при работе над веб-приложениями, где логи могут быть весьма многословными и ошибки легко теряются в общей массе. Ещё одно преимущество этих инструментов в том, что они отображают значения переменных при обнаружении ошибок. Таким образом можно определить, какой URL или пользователь спровоцировал проблему и тому подобное.
Как осуществляется процесс отладки?
Прежде чем начать разговор о логах, необходимо ответить на два вопроса:
- Что такое программа?
- Как осуществляется отладка, в которой логи играют важную роль?
Программа как переходы состояний
Программа — это серия переходов между состояниями.
Состояния — это вся информация, которую программа хранит в своей памяти в определенный момент времени, а код программы определяет то, как она переходит от одного состояния к другому. Разработчики, использующие императивные языки программирования, такие как Java, зачастую акцентируют больше внимания на самом процессе (коде), чем состояниях
Однако понимание того, что программа является серией состояний, очень важно, поскольку они существенно ближе к тому, что должна делать программа, а не как.
Допустим, есть робот, задача которого — заполнить бензобак машины. Если мы рассмотрим выполняемые им действия как переходы состояний, то ему необходимо перейти от состояния (бак пустой, в наличии 50 $) к состоянию (бак полный, в наличии 15 $). Если же мы описываем его как процесс, то он должен найти заправку, доставить туда машину и заплатить. Конечно же, процесс имеет большое значение, но состояния дают более точную оценку правильности программы.
Отладка
Отладка — это мысленная реконструкция переходов состояний. Разработчики проигрывают в уме сценарий программы: как она принимает вводные данные, проходит через ряд изменений состояний и осуществляет вывод, а затем определяют, что пошло не так. Во время разработки этот мыслительный процесс подкрепляется использованием отладчика. Однако в продакшене делать это уже гораздо сложнее, поэтому на данном этапе чаще прибегают к помощи логов.
A Working Example
formatters:
brief:
format: '%(levelname)-8s: %(name)-15s: %(message)s'
precise:
format: '%(asctime)s %(name)-15s %(levelname)-8s %(message)s'
filters:
allow_foo:
name: foo
handlers:
console:
class : logging.StreamHandler
formatter: brief
level : INFO
stream : ext://sys.stdout
filters:
file:
class : logging.handlers.RotatingFileHandler
formatter: precise
filename: logconfig.log
maxBytes: 1024
backupCount: 3
debugfile:
class : logging.FileHandler
formatter: precise
filename: logconfig-detail.log
mode: a
email:
class: logging.handlers.SMTPHandler
mailhost: localhost
fromaddr: my_app@domain.tld
toaddrs:
- support_team@domain.tld
- dev_team@domain.tld
subject: Houston, we have a problem.
loggers:
foo:
level : ERROR
handlers:
spam:
level : CRITICAL
handlers:
propagate: no
bar.baz:
level: WARNING
root:
level : DEBUG
handlers :
Summary
Logging in Python is simple and well-standardized, thanks to a powerful logging framework right in the standard library.
Modules should simply log everything to a logger instance for their module name. This makes it easy for the application to route log messages of different modules to different places, if necessary.
Applications then have several options to configure logging. In a modern infrastructure, though, following best practices simplifies this a great deal. Unless specifically needed, simply logging to / and letting or your container handle log messages is sufficient and the best approach.
Перехват необработанных исключений
Вы не можете предвидеть и обработать все исключения, но можете логировать необработанные исключения, чтобы исследовать их позже.
Необработанное исключение возникает вне или, когда вы не включаете нужный тип исключения в . Например, если приложение обнаруживает , а ваш обрабатывает только , исключение передаётся в другие , пока не встретит нужный тип.
Если ничего не встретилось, исключение становится необработанным. Интерпретатор вызывает с тремя аргументами: класс исключения, его экземпляр и трассировка. Эта информация обычно появляется в , но если вы настроили свой лог для вывода в файл, не логируется.
Вы можете использовать стандартную библиотеку для форматирования трассировки и её включения в лог. Перепишем так, чтобы она пыталась записать количество слов в файл. Неверное число аргументов в вызовет исключение:
# lowermodule.pyimport logging.configimport tracebacklogging.config.fileConfig('logging.ini', disable_existing_loggers=False)logger = logging.getLogger(__name__)def word_count(myfile): try: # считаем слова, логируем результат. with open(myfile, 'r+') as f: file_data = f.read() words = file_data.split(" ") final_word_count = len(words) logger.info("this file has %d words", final_word_count) f.write("this file has %d words", final_word_count) return final_word_count except OSError as e: logger.error(e, exc_info=True) except: logger.error("uncaught exception: %s", traceback.format_exc()) return Falseif __name__ == '__main__': word_count('myfile.txt')
При выполнении этого кода возникнет , не обрабатываемое в . Однако оно логируется благодаря коду, включенному во второе выражение :
# исключение не обрабатывается, но логируется.2019-03-28 15:22:31,121 lowermodule - ERROR:uncaught exception: Traceback (most recent call last): File "/home/emily/logstest/lowermodule.py", line 23, in word_count f.write("this file has %d words", final_word_count)TypeError: write() takes exactly one argument (2 given)
Логирование трассировки обеспечивает критическую видимость ошибок в реальном времени. Вы можете исследовать, когда и почему они произошли.
Многострочные исключения легко читаются, но если вы объединяете свои журналы с внешним сервисом, то далее можно преобразовать их в JSON, чтобы гарантировать корректный анализ. Теперь мы покажем, как использовать для этого .
Унификация
В этом разделе мы покажем, как форматировать журналы в JSON, добавлять пользовательские атрибуты, а также централизовывать и анализировать данные.
Logging from Modules
A well-organized Python application is likely composed of many modules. Sometimes these modules are intended to be used by other programs, but unless you’re intentionally developing reusable modules inside your application, it’s likely you’re using modules available from pypi and modules that you write yourself specific for your application.
In general, a module should emit log messages as a best practice and should not configure how those messages are handled. That is the responsibility of the application.
The only responsibility modules have is to make it easy for the application to route their log messages. For this reason, it is a convention for each module to simply use a logger named like the module itself. This makes it easy for the application to route different modules differently, while also keeping log code in the module simple. The module just needs two lines to set up logging, and then use the named logger:
import logging
log = logging.getLogger(__name__)
def do_something():
log.debug("Doing something!")
That is all there is to it. In Python, contains the full name of the current module, so this will simply work in any module.
Формат вывода
Хотя вы можете передавать любую переменную, которая может быть представлена в виде строки из вашей программы в виде сообщения в ваши журналы, есть некоторые базовые элементы, которые уже являются частью LogRecord и могут быть легко добавлены в выходной формат. Если вы хотите записать идентификатор процесса ID вместе с уровнем и сообщением, вы можете сделать что-то вроде этого:
import logging
logging.basicConfig(format='%(process)d-%(levelname)s-%(message)s')
logging.warning('This is a Warning')
18472-WARNING-This is a Warning
format может принимать строку с атрибутами LogRecord в любом порядке. Весь список доступных атрибутов можно найти .
Вот еще один пример, где вы можете добавить информацию о дате и времени:
import logging
logging.basicConfig(format='%(asctime)s - %(message)s', level=logging.INFO)
logging.info('Admin logged in')
2018-07-11 20:12:06,288 - Admin logged in
%(asctime)s добавляет время создания LogRecord. Формат можно изменить с помощью атрибута datefmt, который использует тот же язык форматирования, что и функции форматирования в модуле datetime, например time.strftime():
import logging
logging.basicConfig(format='%(asctime)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')
logging.warning('Admin logged out')
12-Jul-18 20:53:19 - Admin logged out
Вы можете найти больше информации о формате datetime руководстве.
Логирование переменных
В большинстве случаев вам нужно будет включать динамическую информацию из вашего приложения в журналы. Вы видели, что методы ведения журнала принимают строку в качестве аргумента, и может показаться естественным отформатировать строку с переменными в отдельной строке и передать ее методу log. Но на самом деле это можно сделать напрямую, используя строку формата для сообщения и добавляя переменные в качестве аргументов. Вот пример:
import logging
name = 'John'
logging.error('%s raised an error', name)
ERROR:root:John raised an error
Аргументы, передаваемые методу, будут включены в сообщение в качестве переменных.
Хотя вы можете использовать любой стиль форматирования, f-строки, представленные в Python 3.6, являются лучшим способом форматирования строк, поскольку они могут помочь сделать форматирование коротким и легким для чтения:
import logging
name = 'John'
logging.error(f'{name} raised an error')
ERROR:root:John raised an error
Вывод стека
Модуль регистрации также позволяет вам захватывать стек выполнения в приложении. Информация об исключении может быть получена, если параметр exc_info передан как True, а функции ведения журнала вызываются таким образом:
import logging
a = 5
b = 0
try:
c = a / b
except Exception as e:
logging.error("Exception occurred", exc_info=True)
ERROR:root:Exception occurred
Traceback (most recent call last):
File "exceptions.py", line 6, in <module>
c = a / b
ZeroDivisionError: division by zero
Если для exc_info не задано значение True, выходные данные вышеприведенной программы не сообщат нам ничего об исключении, которое в реальном сценарии может быть не таким простым, как ZeroDivisionError. Представьте, что вы пытаетесь отладить ошибку в сложной кодовой базе с помощью журнала, который показывает только это:
ERROR:root:Exception occurred
Совет: если вы логируете в обработчике исключений (try..except…), используйте метод logging.exception(), который регистрирует сообщение с уровнем ERROR и добавляет в сообщение информацию об исключении. Проще говоря, вызов logging.exception() похож на вызов logging.error (exc_info = True). Но поскольку этот метод всегда выводит информацию об исключении, его следует вызывать только в обработчике исключений. Взгляните на этот пример:
import logging
a = 5
b = 0
try:
c = a / b
except Exception as e:
logging.exception("Exception occurred")
ERROR:root:Exception occurred
Traceback (most recent call last):
File "exceptions.py", line 6, in <module>
c = a / b
ZeroDivisionError: division by zero
Использование logging.exception() покажет лог на уровне ERROR. Если вы не хотите этого, вы можете вызвать любой из других методов ведения журнала от debug() до critical() и передать параметр exc_info как True.
