[Перевод] Полное руководство по логированию в Node.js с помощью Pino27.05.2023 16:31

Это перевод статьи «A Complete Guide to Pino Logging in Node.js», опубликованной 14 апреля 2023-го года Better Stack Team. Но сперва предисловие переводчика.

Предисловие переводчика

Почему именно Pino? Об этом можно посмотреть видео основателя проекта, Маттео Коллина (Matteo Collina), «The Cost of Logging» о цене, которую приходится платить многопользовательским приложениям за кажущуюся совершенно безобидной функцию ведения логов. Суть его выступления в том, что при выборе медленного инструмента логирования и увеличении количества запросов в секунду, оверхед на запись логов становится неприлично высоким. Каждую секунду приложение может тратить большую часть времени только на запись логов.

Чтобы справиться с этой проблемой, и был создан Pino, асинхронный JSON-логгер. В первую очередь именно его асинхронность и позволяет ему быть очень быстрым, создавая минимальный оверхед в системе. Также для максимального ускорения были применены и некоторые другие приёмы, о которых упоминается в видео.

Кроме того, этот логгер является встроенным в набирающем популярность веб-фреймворке Fastify, ведущим разработчиком которого является всё тот же Маттео Коллина. Fastify был создан со всё той же целью — минимизировать оверхед для Node.js-приложений.

Далее перевод оригинальной статьи от Better Stack Team.

О Pino

Pino — это мощная платформа ведения логов для Node.js, обладающая молниеносной скоростью и широкими возможностями. Фактически именно скорость Pino и завоевала ему место логгера по-умолчанию в open-source веб-сервере Fastify. Также Pino способен очень просто интегрироваться с другими Node.js-фреймворками, что делает его лучшим выбором для всех разработчиков, ищущих надёжное и гибкое решение для ведения логов.

В Pino есть все стандартные возможности, которые ожидаются от логгера [кроме разве что ротации логов, которая отдана на откуп внешним приложениям, таким как logrotate — прим. переводчика], такие как настраиваемые уровни логирования, настройки форматирования и всевозможные виды транспортов.

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

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

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

Предварительные требования

Прежде, чем продолжить читать статью, убедитесь, что на вашей машине установлены последние версии Node.js и npm. Также подразумевается, что вы уже знакомы с базовыми особенностями логирования в Node.js.

Начало работы с Pino

Чтобы получить от данного пособия максимум и протестировать все возможности Pino, обсуждаемые далее, создайте новое Node.js-приложение. Для этого выполните следующие команды:

mkdir pino-logging && cd pino-logging
npm init -y

После этого установите последнюю версию Pino с помощью команды ниже. Примеры, приведённые в статье, совместимы с Pino версии 8, последней на момент написания статьи.

npm install pino

Создайте файл logger.js в корневой папке проекта и наполните его следующим содержимым:

// logger.js
const pino = require('pino');

module.exports = pino({});

Этот фрагмент импортирует пакет pino и экспортирует экземпляр логгера, созданный с помощью функции верхнего уровня pino(). Далее в статье мы рассмотрим все возможные способы настройки Pino, но для начала воспользуемся настройками по-умолчанию и импортируем наш логгер в index.js:

//index.js
const logger = require('./logger');

logger.info('Привет, мир!');

После того, как сохраните файл, запустите его командой:

node index.js

Вы должны увидеть следующий вывод:

{"level":30,"time":1677506333497,"pid":39977,"hostname":"fedora","msg":"Привет, мир!"}

Первое, что можно заметить — вывод структурирован в формате JSON, в доминирующем формате промышленного структурированного логирования. Кроме самого сообщения в записи лога присутствуют следующие поля:

• Поле level означает уровень серьёзности события.

• Поле time содержит время в миллисекундах, прошедшее, начиная с 01.01.1970 00:00:00 UTC.

• Поле hostname означает имя машины, на которой запущен процесс.

• Поле pid означает ID запущенного процесса.

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

Форматированный вывод JSON-логов на этапе разработки

Благодаря своим простоте, гибкости и широкой поддержке среди инструментов логирования JSON хорошо подходит для ведения логов в продакшене. Но человеческому глазу сложно воспринимать его напрямую, особенно, если он записан в одну линию. Чтобы сделать логи Pino более удобочитаемыми при разработке (где они зачастую выводятся в консоль), можно применить один из следующих подходов:

1. Использовать jq

Jq — это стильная консольная утилита для обработки JSON. Если передать в неё JSON-логи, то результатом станет их цветной форматированный вывод:  

node index.js | jq

Вывод:

{
  "level": 30,
  "time": 1677669391146,
  "pid": 557812,
  "hostname": "fedora",
  "msg": "Привет, мир!"
}

Если вывод получается слишком громоздким, можно удалить ненужные поля с помощью функции jq del():

node index.js | jq 'del(.time,.hostname,.pid)'

Результат:

{
  "level": 30,
  "msg": "Привет, мир!"
}

Также можно использовать белый список полей, который может быть полезен ещё и в случае, если нужно поменять поля местами:

node index.js | jq '{msg,level}'

Вывод:

{
  "msg": "Привет, мир!",
  "level": 30
}

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

2. Использовать pino-pretty

Команда разработки Pino создала аналогичный jq инструмент — pino-pretty — для преобразования строк JSON в удобочитаемый человеком обычный текст.

Установка pino-pretty:

npm install pino-pretty --save-dev

Передача JSON-логов в pino-pretty:  

node index.js | npx pino-pretty

Вы заметите, что логи сменили свой формат, обрели цвет и стали более удобочитаемыми:

[12:33:00.352] INFO (579951): Привет, мир!

Если хотите изменить форматирование вывода, обратитесь к соответствующей документации по транспорту pino-pretty.

Уровни логирования

В Pino уровни логирования по-умолчанию это (по возрастанию серьёзности): trace,  debug,  info,  warn,  error, и fatal. Для каждого из них существует соответствующий метод логгера:

// index.js
const logger = require('./logger');

logger.fatal('fatal');
logger.error('error');
logger.warn('warn');
logger.info('info');
logger.debug('debug');
logger.trace('trace');

После запуска index.js должен получиться следующий результат:

{"level":60,"time":1643664517737,"pid":20047,"hostname":"fedora","msg":"fatal"}
{"level":50,"time":1643664517738,"pid":20047,"hostname":"fedora","msg":"error"}
{"level":40,"time":1643664517738,"pid":20047,"hostname":"fedora","msg":"warn"}
{"level":30,"time":1643664517738,"pid":20047,"hostname":"fedora","msg":"info"}

Обратите внимание, что поле level представлено в виде числа, увеличивающегося на 10 каждый раз с повышением уровня серьёзности события. Также вы можете обнаружить, что в списке событий нет записей, сгенерированных функциями debug() и trace() — это потому, что по-умолчанию минимальным уровнем вывода в Pino является info, который подавляет вывод событий более низкого уровня.

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

// logger.js
const pino = require('pino');

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
});

В данном примере, если установлена переменная окружения PINO_LOG_LEVEL, будет использоваться её значение, а иначе уровень логирования по-умолчанию будет установлен в значение info. В примере ниже минимальный уровень логирования устанавливается в error, что значит, что все события ниже этого уровня будут проигнорированы:

PINO_LOG_LEVEL=error node index.js

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

set PINO_LOG_LEVEL=error
node index.js

Вывод:

{"level":60,"time":1643665426792,"pid":22663,"hostname":"fedora","msg":"fatal"}
{"level":50,"time":1643665426793,"pid":22663,"hostname":"fedora","msg":"error"}

Изменить минимальный уровень логирования можно в любом месте приложения через объект logger и его свойство level:

// index.js
const logger = require('./logger');

logger.level = 'debug'; // после этого будут отбрасываться только сообщения 
                        // уровня trace
. . .

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

app.get('/changeLevel', (req, res) => {
  const { level } = req.body;
  // проверить, что уровень логирования задан, затем изменить его
  logger.level = level;
});

Настройка уровней логирования

Вы не ограничены теми уровнями логирования, которые Pino предоставляет по-умолчанию. Можно легко добавить любые другие уровни, создав объект, содержащий номера приоритетов для каждого из уровней, и присвоив его свойству customLevels логгера. Например, в коде ниже добавляется уровень notice, более серьёзный, нежели info, но менее серьёзный, нежели warn. 

// logger.js
const pino = require('pino');

const levels = {
  notice: 35, // Подойдёт любое число между 30 (info) и 40 (warn)
};

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
  customLevels: levels,
});

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

// index.js
const logger = require('./logger');

logger.warn('warn');
logger.notice('notice');
logger.info('info');

Результат:

{"level":40,"time":1678192423827,"pid":122107,"hostname":"fedora","msg":"warn"}
{"level":35,"time":1678192423828,"pid":122107,"hostname":"fedora","msg":"notice"}
{"level":30,"time":1678192423828,"pid":122107,"hostname":"fedora","msg":"info"}

Если вы хотите полностью заменить уровни Pino, например, стандартными уровнями Syslog, добавьте опцию useOnlyCustomLevels:

// logger.js
const pino = require('pino');

const levels = {
  emerg: 80,
  alert: 70,
  crit: 60,
  error: 50,
  warn: 40,
  notice: 30,
  info: 20,
  debug: 10,
};

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
  customLevels: levels,
  useOnlyCustomLevels: true,
});

Настройка полей, присутствующих по-умолчанию

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

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

Зададим какому-нибудь уровню логирования строковое имя вместо его числового значения. Сделать это можно с помощью опции formatters:

// logger.js
. . .
module.exports = pino({
level: process.env.PINO_LOG_LEVEL || 'info',
  formatters: {
    level: (label) => {
      return { level: label.toUpperCase() };
    },
  },
});

Код выше переименовывает уровни и меняет регистр их новых строковых имён на верхний:

{"level":"ERROR","time":1677673626066,"pid":636012,"hostname":"fedora","msg":"error"}
{"level":"WARN","time":1677673626066,"pid":636012,"hostname":"fedora","msg":"warn"}
{"level":"INFO","time":1677673626066,"pid":636012,"hostname":"fedora","msg":"info"}

Также можно переименовать само название свойства level на что-нибудь возвращаемое произвольной функцией:

// logger.js
module.exports = pinoLogger({
  level: process.env.PINO_LOG_LEVEL || 'info',
  formatters: {
    level: (label) => {
      return { severity: label.toUpperCase() };
    },
  },
});

Вывод:

{"severity":"ERROR","time":1677676496547,"pid":693683,"hostname":"fedora","msg":"error"}
{"severity":"WARN","time":1677676496547,"pid":693683,"hostname":"fedora","msg":"warn"}
{"severity":"INFO","time":1677676496547,"pid":693683,"hostname":"fedora","msg":"info"}

Настройка формата временной метки

По-умолчанию, временная метка создаётся в формате количества миллисекунд, прошедших с 01.01.1970 00:00:00 UTC (как в выводе функции Date.now()). Вы можете переопределить это поле (timestamp) при создании экземпляра логгера. Мы рекомендуем выводить временные метки в формате ISO-8601:

// logger.js
const pino = require('pino');

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
  formatters: {
    level: (label) => {
      return { level: label.toUpperCase() };
    },
  },
  timestamp: pino.stdTimeFunctions.isoTime,
});

Результат:

{"level":"INFO","time":"2023-03-01T12:36:14.170Z","pid":650073,"hostname":"fedora","msg":"info"}

Также вы можете переименовать свойство time в timestamp с помощью функции, которая возвращает частичное JSON-представление текущего времени (предваряемое запятой) как в примере ниже:

pino({
  timestamp: () => `,"timestamp":"${new Date(Date.now()).toISOString()}"`,
})

Вывод:

{"label":"INFO","timestamp":"2023-03-01T13:19:10.018Z","pid":698279,"hostname":"fedora","msg":"info"}

Изменение встроенных полей лога

В Pino существуют ещё два встроенных поля, которые по-умолчанию добавляются к каждой записи лога: ID процесса (pid) и имя хоста (hostname). Вы можете переопределить их с помощью функции bindings в разделе formatters. Например, давайте переименуем hostname в host:

// logger.js
const pino = require('pino');

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
  formatters: {
    bindings: (bindings) => {
      return { pid: bindings.pid, host: bindings.hostname };
    },
    level: (label) => {
      return { level: label.toUpperCase() };
    },
  },
  timestamp: pino.stdTimeFunctions.isoTime,
});

Вывод:

{"level":"INFO","time":"2023-03-01T13:24:28.276Z","process_id":707519,"host":"fedora","msg":"info"}

Вы можете удалить любые встроенные поля из возвращаемого объекта, а также добавить любые поля по вашему желанию — и они будут присутствовать в каждой записи лога. Ниже приведён пример, в котором в каждую запись лога добавляется версия Node.js, используемой для запуска приложения:

bindings: (bindings) => {
  return {
    pid: bindings.pid,
    host: bindings.hostname,
    node_version: process.version,
  };
},

Вывод:

{"level":"INFO","time":"2023-03-01T13:31:28.940Z","pid":719462,"host":"fedora","node_version":"v18.14.0","msg":"info"}

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

Добавление контекстуальных данных

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

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

В Pino основным способом добавления контекстуальных данных является определение параметра mergingObject в вызываемом методе логгера:

logger.error(
  { transaction_id: '12343_ff', user_id: 'ivanov' },
  'Транзакция провалилась'
);

Фрагмент выше породит следующий результат:

{"level":"ERROR","time":"2023-03-01T13:47:00.302Z","pid":737430,"hostname":"fedora","transaction_id":"12343_ff","user_id":"ivanov","msg":"Транзакция провалилась"}

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

// index.js
const logger = require('./logger');

logger.info('Запуск программы');

function getUser(userID) {
  const childLogger = logger.child({ userID });
  childLogger.trace('getUser запущен');
  
  // получить данные пользователя и вернуть их из функции
  
  childLogger.trace('getUser завершён');
}

getUser('ivanov');

logger.info('Завершение программы');

Выполните этот код с установленным минимальным уровнем логирования trace:

PINO_LOG_LEVEL=trace node index.js

Примечание переводчика. Для Windows-систем команды будут следующими:

set PINO_LOG_LEVEL=trace 
node index.js

Результат:

{"level":"INFO","time":"2023-03-01T14:15:47.168Z","pid":764167,"hostname":"fedora","msg":"Запуск программы"}
{"level":"TRACE","time":"2023-03-01T14:15:47.169Z","pid":764167,"hostname":"fedora","userID":"ivanov","msg":"getUser запущен"}
{"level":"TRACE","time":"2023-03-01T14:15:47.169Z","pid":764167,"hostname":"fedora","userID":"ivanov","msg":"getUser завершён"}
{"level":"INFO","time":"2023-03-01T14:15:47.169Z","pid":764167,"hostname":"fedora","msg":"Завершение программы"}

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

Логирование ошибок

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

Метод error() логгера может в качестве первого аргумента принять объект ошибки. А сообщение об ошибке в этом случае станет вторым аргументом:

// index.js
const logger = require('./logger');

function alwaysThrowError() {
  throw new Error('обработка ошибки');
}

try {
  alwaysThrowError();
} catch (err) {
  logger.error(err, 'Возникла непредвиденная ошибка в процессе обработки запроса');
}

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

{
  "level": "ERROR",
  "time": "2023-03-01T14:28:17.821Z",
  "pid": 781077,
  "hostname": "fedora",
  "err": {
    "type": "Error",
    "message": "обработка ошибки",
    "stack": "Error: обработка ошибки\n    at alwaysThrowError (/home/ayo/dev/betterstack/community/demo/pino-logging/main.js:4:9)\n    at Object. (/home/ayo/dev/betterstack/community/demo/pino-logging/main.js:8:3)\n    at Module._compile (node:internal/modules/cjs/loader:1226:14)\n    at Module._extensions..js (node:internal/modules/cjs/loader:1280:10)\n    at Module.load (node:internal/modules/cjs/loader:1089:32)\n    at Module._load (node:internal/modules/cjs/loader:930:12)\n    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n    at node:internal/main/run_main_module:23:47"
  },
  "msg": "Возникла непредвиденная ошибка в процессе обработки запроса"
}

Обработка неотловленных исключений и необработанных отказов промисов

В Pino нет специального механизма для логирования неотловленных исключений или отказов промисов, поэтому вы должны самостоятельно прослушивать события uncaughtException и unhandledRejection и ещё до выхода из приложения логировать эти исключения с уровнем FATAL (после попытки мягкого завершения):  

process.on('uncaughtException', (err) => {
  // залогировать исключение
  logger.fatal(err, 'обнаружено неотловленное исключение');
  
  // мягко завершить работу сервера
  
  server.close(() => {
    process.exit(1); // затем выйти
  });

  // если не удалось завершить работу мягко в течение 1 секунды, 
  // завершить процесс полностью
  setTimeout(() => {
    process.abort(); // выйти немедленно и создать файл дампа
  }, 1000).unref()
  
  process.exit(1);
});

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

Транспорты

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

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

Ниже приведён пример использования встроенного транспорта pino/file, который перенаправляет логи в файл (или файловый дескриптор):

// logger.js
const pino = require('pino');

const fileTransport = pino.transport({
  target: 'pino/file',
  options: { destination: `${__dirname}/app.log` },
});

module.exports = pino(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    formatters: {
      level: (label) => {
        return { level: label.toUpperCase() };
      },
    },
    timestamp: pino.stdTimeFunctions.isoTime,
  }, 
  fileTransport
);

Другой способ записать логи в файл (или файловый дескриптор) заключается в использовании pino.destination () API:

// logger.js
const pino = require('pino');

module.exports = pino(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    formatters: {
      level: (label) => {
        return { level: label.toUpperCase() };
      },
    },
    timestamp: pino.stdTimeFunctions.isoTime,
  }, 
  pino.destination(`${__dirname}/app.log`)
);

Обратите внимание, что транспорт pino/file под капотом использует pino.destination(). Основная разница между ними в том, что первый выполняется в отдельном воркере, а второй — в основном потоке. Если логировать только в стандартный вывод или локальные файлы, то использование pino/file может внести некоторый оверхед, так как сперва данные должны быть вынесены из основного потока. Возможно, в таких случаях стоит использовать именно pino.destination(). Pino/file рекомендуется использовать только в случае логирования сразу в несколько точек назначения, например, и в файл и в стороннюю службу управления логами.

Кроме того, Pino поддерживает «устаревшие транспорты», которые выполняются в отдельном от Node.js процессе. Для бо́льших подробностей обратитесь к соответствующей документации.

Логирование в несколько точек назначения

Запись логов одновременно в несколько точек назначения очень распространено, и в транспортах Pino начиная с 7-й версии эта возможность также поддерживается. Для этого вам необходимо создать массив targets и поместить все объекты транспортов внутрь него:

// logger.js
const pino = require('pino');

const transport = pino.transport({
  targets: [
    {
      target: 'pino/file',
      options: { destination: `${__dirname}/app.log` },
    },
    {
      target: 'pino/file', // по-умолчанию логирует в стандартный вывод
    },
  ],
});

module.exports = pino(
  {
    level: process.env.PINO_LOG_LEVEL || 'info',
    timestamp: pino.stdTimeFunctions.isoTime,
  }, 
  transport
);

Выше приведена настройка Pino на логирование одновременно и в стандартный вывод и в файл app.log. Обратите внимание, что функцию formatters.level невозможно использовать при логировании во множественные точки назначения, поэтому она и не была использована в коде выше. Если всё же попытаться её использовать, то произойдёт следующая ошибка:  

Error: option.transport.targets do not allow custom level formatters

Чтобы в консоли отобразился красивый отформатированный вывод вместо сырого JSON, вторую точку назначения можно изменить на pino-pretty (который должен быть предварительно установлен):

const transport = pino.transport({
  targets: [
    {
      target: 'pino/file',
      options: { destination: `${__dirname}/app.log` },
    },
    {
      target: 'pino-pretty',
    },
  ],
});

Запуск:

node index.js && echo $'\n' && cat app.log

Примечание переводчика. Для Windows-систем команда запуска будет следующей:

node index.js && echo: && type app.log

Вывод:

[14:33:41.932] INFO (259060): info
[14:33:41.933] ERROR (259060): error
[14:33:41.933] FATAL (259060): fatal
{"level":30,"time":"2023-03-03T13:33:41.932Z","pid":259060,"hostname":"fedora","msg":"info"}
{"level":50,"time":"2023-03-03T13:33:41.933Z","pid":259060,"hostname":"fedora","msg":"error"}
{"level":60,"time":"2023-03-03T13:33:41.933Z","pid":259060,"hostname":"fedora","msg":"fatal"}

Конфиденциальность при логировании

Одна из важнейших лучших практик при логировании — это контроль над утечкой в логи конфиденциальной информации. Примерами таких данных могут быть:

• Финансовые данные, такие как номера банковских карт, пин-коды, номера банковских счетов и т. д.

• Пароли или другие секретные данные приложения.

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

• Медицинские записи.

• Данные биометрии и прочее.

Запись чувствительной информации в логи может привести к утечкам данных, краже личности, несанкционированному доступу или другим зловредным действиям, которые могут полностью разрушить репутацию вашего бизнеса. Также это может привести к штрафам и другим санкциям в отношении вашего бизнеса от таких органов как GDPR, PCI и HIPPA [европейские и американские регуляторы в области защиты конфиденциальной информации — примечание переводчика]. Чтобы предотвратить подобные происшествия, необходимо всегда проверять ваши логи с целью предотвращения случайного попадания в них чувствительных данных.

Существует несколько практик, которые помогут вам не допустить попадания такой информации в логи. Их все невозможно обсудить в рамках данной статьи, поэтому мы сосредоточимся только на практике редактирования логов — технике выявления и удаления конфиденциальных данных с сохранением информации, необходимой для диагностики или анализа. В Pino для реализации этой функции используется npm-пакет fast-redact.

Например, у нас есть объект user со следующей структурой:

const user = {
  id: 'ivanov',
  name: 'Иван Иванов',
  address: 'Улица Сезам, 123',
  passport: {
    number: '123 456',
    issued: 2023,
    expires: 2027,
  },
  phone: '123-456-789',
};

Если залогировать этот объект как есть, то он раскроет такие чувствительные данные как имя пользователя, его адрес, паспортные данные и телефонный номер:  

logger.info({ user }, 'Пользователь обновлён');

Вывод:

{
  "level": "info",
  "time": 1677660968266,
  "pid": 377737,
  "hostname": "fedora",
  "user": {
    "id": "ivanov",
    "name": "Иван Иванов",
    "address": "Улица Сезам, 123",
    "passport": {
      "number": "123 456",
      "issued": 2023,
      "expires": 2027
    },
    "phone": "123-456-789"
  },
  "msg": "Пользователь обновлён"
}

Чтобы этого не произошло, необходимо заранее настроить ваш логгер на удаление секретных полей:

// logger.js
const pino = require('pino');

module.exports = pino({
  level: process.env.PINO_LOG_LEVEL || 'info',
  formatters: {
    level: (label) => {
      return { level: label };
    },
  },
  redact: ['user.name', 'user.address', 'user.passport', 'user.phone'],
});

Опция redact определяет массив полей, данные которых должны вырезаться при записи логов. Данный пример приведёт к тому, что из логов будут вырезаны данные полей name, address, passport и phone в любом объекте user. Вместо них будет отображена надпись [Redacted]. В результате в логах можно будет прочитать только значение поля id:  

{
  "level": "info",
  "time": 1677662887561,
  "pid": 406515,
  "hostname": "fedora",
  "user": {
    "id": "ivanov",
    "name": "[Redacted]",
    "address": "[Redacted]",
    "passport": "[Redacted]",
    "phone": "[Redacted]"
  },
  "msg": "Пользователь обновлён"
}

Вы можете изменить надпись-заполнитель с помощью следующей настройки:

module.exports = pino({
  redact: {
    paths: ['user.name', 'user.address', 'user.passport', 'user.phone'],
    censor: '[ТАЙНА]',
  },
});

Вывод:

{
  "level": "info",
  "time": 1677663111963,
  "pid": 415221,
  "hostname": "fedora",
  "user": {
    "id": "ivanov",
    "name": "[ТАЙНА]",
    "address": "[ТАЙНА]",
    "passport": "[ТАЙНА]",
    "phone": "[ТАЙНА]"
  },
  "msg": "Пользователь обновлён"
}

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

module.exports = pino({
  redact: {
    paths: ['user.name', 'user.address', 'user.passport', 'user.phone'],
    censor: '[ТАЙНА]',
    remove: true,
  },
});

Результат:

{
  "level": "info",
  "time": 1677663213497,
  "pid": 419647,
  "hostname": "fedora",
  "user": {
    "id": "ivanov"
  },
  "msg": "Пользователь обновлён"
}

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

// здесь наш фильтр сработает
logger.info({ user }, 'Пользователь обновлён');
// а здесь не сработает
logger.info({ nested: { user } }, 'Пользователь обновлён');
logger.info(user, 'Пользователь обновлён');

Чтобы избежать этого, обновим фильтр:

module.exports = pino({
  redact: {
    paths: [
      'name',
      'address',
      'passport',
      'phone',
      'user.name',
      'user.address',
      'user.passport',
      'user.phone',
      '*.user.name', // * — шаблон с уровнем вложенности 1
      '*.user.address',
      '*.user.passport',
      '*.user.phone',
    ],
    remove: true,
  },
});

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

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

Логирование HTTP-запросов

Pino можно использовать для логирования HTTP-запросов в любом Node.js-приложении вне зависимости от того, каким фреймворком вы пользуетесь. Пользователи Fastify уже могли заметить, что Pino встроен в этот фреймворк. По-умолчанию отключён, поэтому сперва его нужно включить:

const fastify = require('fastify')({
  logger: true
})

После этого Pino начнёт логировать все входящие запросы в следующем виде:

{"level":30,"time":1675961032671,"pid":450514,"hostname":"fedora","reqId":"req-1","res":{"statusCode":200},"responseTime":3.1204520016908646,"msg":"запрос обработан"}

Если вы используете другой фреймворк, посетите страницу экосистемы Pino, чтобы найти специфичную для него интеграцию. Пример далее показывает как использовать npm-пакет pino-http, чтобы логировать HTTP-запросы в Express:

// index.js
const express = require('express');
const logger = require('./logger');
const axios = require('axios');
const pinoHTTP = require('pino-http');

const app = express();

app.use(
  pinoHTTP({
    logger,
  })
);

app.get('/crypto', async (req, res) => {
  try {
    const response = await axios.get('https://api2.binance.com/api/v3/ticker/24hr');
    const tickerPrice = response.data;
      res
    .json(tickerPrice© Habrahabr.ru