Данное руководство служит рекомендациями для авторов библиотек относительно того, какие уровни логирования SwiftLog подходят для использования в библиотеках и в каких ситуациях следует использовать тот или иной уровень.

Библиотеки должны корректно работать в различных сценариях использования и не могут предполагать, что будет использоваться конкретный бэкенд для логирования. Разработчикам, реализующим конкретные приложения и системы, предстоит настроить эти особенности своего приложения, и некоторые могут выбрать логирование в диск, в память или могут использовать сложные агрегаторы логов. Во всех этих случаях библиотека должна вести себя «корректно», что означает, что она не должна перегружать типичные («stdout») бэкенды логирования излишним логированием, избыточным использованием уровня error и т. д.

Данное руководство предназначено для авторов библиотек, касательно того, какие уровни логирования SwiftLog подходят для использования в библиотеках, а также общие подсказки по стилю логирования.

Рекомендации для библиотек

SwiftLog определяет следующие 7 уровней логирования через Logger.Level перечисление, упорядоченные от наименее до наиболее серьезных:

• trace
• debug
• info
• notice
• warning
• error
• critical

Из них только уровни менее серьезные, чем info (исключительно) обычно могут использоваться библиотеками: debug и trace.

В следующем разделе мы рассмотрим, как использовать их на практике.

Рекомендуемые уровни логирования

Для библиотек всегда допустимо логирование на уровнях trace и debug, и эти два уровня должны быть основными уровнями логирования для любой библиотеки.

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

Это в отличие от debug, которое некоторые пользователи могут включить в своих производственных системах.

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

Логирование на уровне отладки не должно полностью подрывать производительность производственной системы.

Таким образом, логирование на уровне debug должно предоставлять пользователям ценное понимание происходящего в библиотеке, используя соответствующий предметной области язык. Логирование на уровне debug не должно быть чрезмерно шумным или углубляться в детали; для этого предназначен уровень trace.

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

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

Логирование на уровне error аналогично предупреждениям: старайтесь избегать этого, когда это возможно. Вместо этого сообщайте об ошибках через API вашей библиотеки. Например, не стоит логировать «соединение не удалось» из HTTP-клиента. Возможно, конечный пользователь намеревался выполнить этот запрос на известный оффлайн-сервер, чтобы подтвердить, что он оффлайн? С их точки зрения, эта ошибка подключения не является «реальной» ошибкой, это просто то, что они ожидали — поэтому HTTP-клиент должен возвращать или выбрасывать такую ошибку, но не логировать её.

Обратите также внимание на то, что в ситуациях, когда вы решили залогировать ошибку, будьте внимательны к частоте ошибок. Будет ли эта ошибка потенциально регистрироваться для каждой отдельной операции во время сетевой неполадки? Некоторые команды и компании имеют системы оповещения, основанные на частоте ошибок, зарегистрированных в системе, и если она превышает определенный порог, они могут начать звонить и вызывать людей посреди ночи. При логировании на уровне ошибок подумайте, действительно ли проблема заслуживает пробуждения людей посреди ночи. Вы также можете рассмотреть возможность предоставления конфигурации в вашей библиотеке: «на каком уровне логирования должно быть сообщено об этой проблеме?». Это может быть полезно в кластеризованных системах, которые могут регистрировать сетевые сбои сами по себе или зависят от внешних систем для обнаружения и регистрации этого.

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

Некоторые библиотеки и ситуации могут быть не совсем ясными относительно того, какой уровень логирования «лучше» для них. В таких ситуациях иногда стоит предоставить конечным пользователям библиотеки возможность настроить уровни для определённых групп сообщений. Вы можете увидеть это в действии в библиотеке Soto здесь, где объект Options позволяет конечным пользователям настроить уровень, на котором регистрируются запросы (options.requestLogLevel), который затем используется как log.log(self.options.requestLogLevel).

Примеры

Логирование на уровне trace:

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

Логирование на уровне debug:

• Может включать одно сообщение о подключении, приёме запроса и так далее.
• Он может включать общее представление о потоке управления в операции. Например: «начало работы, обработка шага X, принято решение X, окончание работы X, код результата 200». Это общее представление может содержать структурированные данные высокой кратности.

Также можно рассмотреть использование swift-distributed-tracing для документирования событий «начало» и «конец», так как трассировка может предоставить дополнительный анализ поведения вашей системы, которого вы бы не получили, просто анализируя сообщения журнала.

Уровни логирования, которых следует избегать

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

Обычно недопустимо, чтобы клиент сервиса (например, HTTP-клиент) регистрировал error, когда запрос завершился неудачно. Конечные пользователи могут использовать клиент для определения, отвечает ли конечная точка вообще или нет, и отсутствие ответа может быть ожидаемым поведением. Логирование ошибок только спутает и засорит их журналы.

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

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

Примеры (чего следует избегать)

Избегайте использования info или любого более серьезного уровня логирования для:

• «Нормальной работы» библиотеки, нет необходимости регистрировать на уровне информации «принял запрос», так как это нормальная работа веб-сервиса.

Избегайте использования error или warning:

• Для отчета об ошибках, которые конечный пользователь библиотеки может самостоятельно регистрировать. Например, если драйвер базы данных не может извлечь все строки запроса, он не должен регистрировать ошибку или предупреждение, а вместо этого возвращать или генерировать ошибку в потоке значений (или функции, асинхронной функции или даже асинхронной последовательности), которая предоставляла возвращенные значения.
  • Поскольку конечный пользователь потребляет эти значения и имеет возможность сообщить (или проглотить) эту ошибку, библиотека не должна регистрировать ничего от его имени.
• Никогда не регистрировать как предупреждения то, что является просто информацией. Например, «обнаружен странный заголовок» может показаться хорошей идеей для регистрации как предупреждения на первый взгляд, однако если «странный заголовок» — это просто неправильно настроенный клиент (или просто «странный браузер»), вы можете случайно полностью залить логи конечного пользователя этими предупреждениями о «странном заголовке» (!)
  • Регистрируйте предупреждения только об имеющих отношение к делу вещах, которые конечный пользователь вашей библиотеки может исправить. Используя пример с логом «обнаружен странный заголовок»: это не является хорошим кандидатом для регистрации как предупреждения, потому что разработчик сервера не может заставить пользователей их сервиса перестать отправлять странные заголовки, поэтому сервер не должен регистрировать эту информацию как предупреждение. Однако, возможно, ее всё ещё целесообразно регистрировать на уровне debug.
• Может возникнуть соблазн реализовать технику «регистрации как предупреждения только один раз» для ситуаций типа «запрос» применительно к ситуациям, которые почти заслуживают быть предупреждениями, но при этом не должны регистрироваться повторно. Авторы могут придумать умные техники, чтобы регистрировать предупреждение только один раз при обнаружении «странного заголовка», а затем впоследствии регистрировать ту же проблему на другом уровне, например, на уровне отслеживания… Такие методы приводят к путанице и трудно отлаживаемым логам, где разработчики системы, не осведомлённые о поточно-состоятельном характере ведения журнала, будут сбиты с толку, пытаясь воспроизвести проблему.
  • Например, если разработчик обнаружит такое предупреждение в системе производства, он может попытаться воспроизвести его — думая, что это происходит только в среде производства. Однако, если выбор уровня логирования в системе ведения журнала является поточно-состоятельным, он может успешно воспроизвести проблему, но никогда не увидит ее проявления. По этим и связанным с ними причинам производительности (поскольку реализация «только один раз на X» подразумевает растущий объём хранения и дополнительные проверки на каждый запрос), не рекомендуется применять этот шаблон.

Исключения из правила «избегать регистрации предупреждений»:

• «Фоновые процессы», такие как задачи, запланированные на периодический таймер, могут не иметь других способов сообщить о сбое или предупреждении конечному пользователю библиотеки, кроме как через ведение журнала.
  • Подумайте о предоставлении API, который будет собирать ошибки во время выполнения, и тогда вы сможете избежать ручного ведения журнала ошибок. Это часто может быть реализовано в виде настраиваемого обработчика «при ошибке», который библиотека принимает при построении запланированной задачи. Если обработчик не настраивается, мы можем вести журнал ошибок, но если он был настроен, то опять-таки конечный пользователь библиотеки решает, что с ними делать.
• Исключением из правила «вести журнал предупреждения только один раз» является ситуация, когда события не происходят слишком часто. Например, если библиотека предупреждает об устаревшей лицензии или чем-то подобном во время ее инициализации, это не обязательно плохая идея. В конце концов, мы предпочитаем видеть это предупреждение один раз во время инициализации, а не при каждом запросе к библиотеке. Используйте свое лучшее суждение и учитывайте разработчиков, использующих вашу библиотеку, при разработке того, как часто и откуда регистрировать такую информацию.

Избегайте изменения уровня логирования или обработчика логирования

Код библиотеки должен генерировать информативные логи и позволять текущему Logger’s LogHandler обрабатывать фильтрацию и фактическое экспортирование логов в систему бэкенда. Целевой исполняемый файл, который связывает библиотеку, отвечает за настройку LogHandler и уровней логирования.

Это антипаттерн для библиотеки — изменять уровень логирования или LogHandler Logger, поэтому избегайте кода такого вида:

// ⚠️ Avoid mutating log levels in libraries
var localLogger = logger
localLogger.logLevel = .warning
// ...

И так:

// ⚠️ Avoid creating loggers with a log handler factory in libraries
let localLogger = Logger(label: "Local", factory: ...)
// ...

Любой подобный код должен быть включен в целевой исполняемый файл вместо этого.

Рекомендованный стиль логирования

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

Прежде всего, важно помнить, что как сообщение оператора лога, так и метаданные в swift-log являются автозакрываемыми, которые вызываются только в том случае, если у логгера установлен уровень логирования, такой, что он должен выдать сообщение для данного сообщения. Таким образом, сообщения, записанные на уровне trace, не «материализуют» свое строковое и метаданные представление, если они на самом деле не нужны:

    public func debug(_ message: @autoclosure () -> Logger.Message,
                      metadata: @autoclosure () -> Logger.Metadata? = nil,
                      source: @autoclosure () -> String? = nil,
                      file: String = #file, function: String = #function, line: UInt = #line) {

И небольшой, но важный совет: избегайте вставлять новые строки и другие управляющие символы в операторы лога (!). Многие системы агрегирования логов предполагают, что одна строка в выводе лога — это одно конкретное «сообщение лога», что может случайно нарушиться, если мы будем регистрировать не отформатированные, потенциально многострочные строки. Это не проблема для всех бэкендов логов. Например, некоторые автоматически очищают и формируют JSON-груз с {message: "..."} перед отправкой его в службу бэкенда, собирающую логи, но обычные логгеры потоков (или файлов) обычно предполагают, что одна строка равна одному сообщению лога. Это также повышает надёжность поиска в логах.

Структурированное логирование (Семантическое логирование)

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

Это превосходный шаблон, который упрощает и делает более надежным автоматизированную обработку записанной информации.

Рассмотрим следующий «неструктурированный» оператор лога:

// NOT structured logging style
log.info("Accepted connection \(connection.id) from \(connection.peer), total: \(connections.count)")

Он содержит 4 фрагмента информации:

• Мы приняли соединение.
• Это его строковое представление.
• Это от этого узла.
• У нас в настоящее время connections.count активных соединений.

Хотя этот оператор лога содержит всю полезную информацию, которую мы хотели передать конечным пользователям, его сложно визуально и механически проанализировать. Например, если мы знаем, что соединения начинают сбоить примерно в тот момент, когда мы достигаем 100 одновременных соединений, то нетривиально найти конкретное сообщение лога, в котором мы достигли этого числа. Мы должны grep 'total: 100', например, однако, возможно, существуют и многие другие "total: " строки, присутствующие во всех наших системах логирования.

Вместо этого мы можем выразить ту же информацию, используя шаблон структурированного логирования следующим образом:

log.info("Accepted connection", metadata: [
  "connection.id": "\(connection.id)",
  "connection.peer": "\(connection.peer)",
  "connections.total": "\(connections.count)"
])

// example output:
// <date> info [connection.id:?,connection.peer:?, connections.total:?] Accepted connection

Этот структурированный лог может быть отформатирован, в зависимости от бэкенда логирования, немного по-разному на различных системах. Даже в простом строковом представлении такого лога мы сможем найти connections.total: 100, а не пытаться угадать правильную строку.

Кроме того, поскольку сообщение теперь не содержит много «читаемого человеком текста», оно менее подвержено случайным изменениям от «Принято» до «Мы приняли» или наоборот. Такого рода изменения могут нарушить системы оповещения, которые настроены на анализ и оповещение о конкретных сообщениях логов.

Структурированные логи очень полезны в сочетании с swift-distributed-tracing’s LoggingContext, которая автоматически заполняет метаданные любой имеющейся информацией о трассировке. Благодаря этому, все логи, созданные в ответ на определенный запрос, автоматически содержат один и тот же TraceID.

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

• https://tersesystems.com/blog/2020/05/26/why-i-wrote-a-logging-library/
• https://cloud.google.com/logging/docs/structured-logging
• https://stackify.com/what-is-structured-logging-and-why-developers-need-it/
• https://kubernetes.io/blog/2020/09/04/kubernetes-1-19-introducing-structured-logs/

Логирование с идентификаторами корреляции / идентификаторами трассировки

Очень распространенным шаблоном является регистрация сообщений с каким-либо «идентификатором корреляции». Лучший подход в общем случае — использовать LoggingContext из swift-distributed-tracing, так как тогда ваша библиотека сможет отслеживаться и использоваться с контекстами корреляции независимо от того, какую систему трассировки использует конечный пользователь (например, open telemetry, zipkin, xray и другие системы трассировки). Однако концепцию можно хорошо объяснить с помощью простого вручную зарегистрированного requestID, что мы объясним ниже.

Рассмотрим HTTP-клиент в качестве примера библиотеки, у которой много метаданных о запросе, например, что-то вроде этого:

log.trace("Received response", metadata: [
   "id": "...",
   "peer.host": "...",
   "payload.size": "...",
   "headers": "...",
   "responseCode": "...",
   "responseCode.text": "...",
])

Точные метаданные не важны, они просто служат заполнителями в этом примере. Важно то, что их «много».

Примечание об именах метаданных: хотя нет единственно правильного способа структурировать имена метаданных, мы рекомендуем думать о них так, как о ключах JSON: camelCased и .-разделенные идентификаторы. Это позволяет многим бэкендам анализа логов обрабатывать их как такую вложенную структуру.

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

// ...
log.trace("Something something...", metadata: ["id": "..."])
log.trace("Finished streaming response", metadata: ["id": "..."]) // good, the same ID is propagated

Благодаря идентификатору корреляции (или идентификатору, предоставленному для отслеживания, в этом случае мы будем записывать как context.log.trace("..."), так как идентификатор автоматически передается), в каждой последующей записи в журнал после начальной записи в журнал мы можем связать все эти записи в журнал. Тогда мы знаем, что это сообщение "Finished streaming response" относилось к ответу с responseCode, который мы можем найти в сообщении журнала "Received response".

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

Рекомендации по использованию журналирования с идентификатором корреляции

При ведении журнала с контекстами корреляции убедитесь, что вы никогда не «теряете ID». Легче всего добиться этого при использовании распределенного отслеживания LoggingContext, так как передача гарантирует сохранение идентификаторов, однако то же самое относится к любому виду идентификатора корреляции.

В частности, избегайте таких ситуаций:

debug: connection established [connection-id: 7]
debug: connection closed unexpectedly [error: foobar] // BAD, the connection-id was dropped

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

Исключения из правил

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

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

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

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

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