О логгировании в Node.js

  • Tutorial
Для начала повторю то, что каждый разработчик должен знать об этом — надо предохраняться.


Зачем надо логгировать


Вы запустили серверное приложение у которого нету GUI для отображения своего состояния, а знать очень хочется. Самое простое и очевидное решение, выводить какие то сообщения куда то — stdout/stderr, файлики, syslog, что-то более извращенное. Это и есть логирование (спасибо кэп).

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

  1. Анализ поведения и производительности. Здесь надо заметить, что для анализа производительности, лучше использовать проббирование (н-р twitter zipkin получает данные через пробы в коде). К поведению относится все, что сейчас происходит.
  2. Анализ и диагностика проблем. Тут очевидно — в приложении критическая ситуация 1/0 (причем не важно когда она произошла, приложение вот вот издохнет), что делать? Правильно — залоггировать это. О об этом подробнее чуть ниже.
  3. Всякие левые сценарии использования.


Как логгировать


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

То есть пишем, что вы сами считаете нужным, для того, чтобы вам было понятно, что происходит. Но надо подчеркнуть, что логгирование ест ресурсы приложения — так что не надо увлекаться, я видел приложение однажды, где логгирование жрало примерно 50% производительности (это конечно же ппц не надо так делать).

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

Уровни логов


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

  1. ERROR — приложение в критическом положении, требуется внимание человека для продолжения. Появляется довольно редко, но метко. Я использую его для очень низкоуровневых вещей или для необработанных исключений
  2. WARN — произошло что-то необычное, выбивающееся из обычного сценария, но приложение умное и восстановило свою работу само. Я использую этот уровень в обрабочиках ошибок.
  3. INFO — что сейчас происходит
  4. DEBUG — что сейчас происходит, более подробно
  5. TRACE — пишем как в твиттер, все что не попадя.


Далее будут небольшое сравнение логгеров, которые я опробовал в node.js и что в них не так, с учетом написанного выше.

log4js


Это первое на что я посмотрел, в надежде что это хоть сколько нибудь будет похоже на log4j.

Маленький пример:
var log4js = require('log4js');
var logger = log4js.getLogger();
logger.debug("Some debug messages");

В консоли появится цветное сообщение:
[2014-01-13 20:41:22.604] [DEBUG] [default] - Some debug messages

В этом логгере есть необходимый минимум. Есть фильтрация сообщений по уровню и категории (имени логгера), время сообщения и возможность его изменить. Для вывода сообщений использутся util.format — поэтому поддерживаются те же опции форматирования, что и в console.log.

winston


Его часто рекомендуют на SO. Я лично ни кому бы его не рекомендовал.
Пример:
var winston = require('winston');
winston.info('Hello distributed log files!');

Что будет в консоли:
info: Hello distributed log files!

В этом месте был небольшой опус о том, что winston не позволяет выдавать время записей, благодаря Keenn, оказалось, что все таки можно, но эти опции (timestamp: true у транспортов) выключены по умолчанию, что очень странно.

bunyan


В отличии от двух предыдущих библиотек этот логгер вместо текста выдает JSON. Создатель решил, что логи все равно разбираются машиной (коллекторами логгов), то пусть это будет машиночитаемый формат. Это хорошо подходит под первый сценарий логирования (очевидно, что собирать пробы руками — это как минимум глупо), но не всегда используются коллекторы. Что лично мне показалось странным, или лучше сказать неудачным решением:
  1. JSON для второго сценария, который на мой взгляд наиболее разумное применение логирования, это как искать в ассемблерном коде ошибку в С++ коде. Логи читают люди. Если приложение небольшое, коллектор логов избыточен, а если появился, то нужно просто добавить для него обработчик.
  2. Если говорить об организации кода, то что обработчик логгера выплевывает и куда, это полностью ответственность обработчика — то есть по идее вывод JSON можно прикрутить к любой библиотеке которая позволяет писать свои обработчики/форматтеры.
  3. У bunyan есть одна фича — сериализаторы для пользовательских типов. Вместе с сообщением логгеру скармливается пачка объектов и он их сериализует. Если посмотреть на это под другим углом:
    сериализация — это просто JSON представление объекта; каждый объект может определить у себя в прототипе метод toJSON и он будет вызван при JSON.stringify — вот и сериализатор; теперь как его вывести — абсолютно все логгеры позволяют выводить json представление объектов специальным флагом (для util.format это %j). То есть фича вроде как достаточно очевидная.

Я честно признаюсь, опыта использования этого логгера у меня почти нет (я пробовал его прикрутить самым первым — все таки joyent использует его), если мне покажут/укажут/ткнут носом, что в нем крутого, я с радостью послушаю и приму к сведению. Хотя я заметил, что есть простейшая организация иерархий логгеров, но ее использовать мне не показалось удобным.

intel


Это самое лучшая библиотека для логгирования, которая мне попалась. В плане конфигурации у меня к ней не было ни каких нареканий. Почему она мне понравилась:
  1. Как уже сказал, у нее очень удобная конфигурация, настроить можно все в одном месте. У логгеров есть обработчики, у обработчиков есть форматтеры сообщений, фильтры по сообщениям и уровням. Почти сказка.
  2. Иерархии логгеров, кто пришел н-р с slf4j считает это само собой разумеющимся, однако же только в этой либе это было нормально реализовано. Что такое иерархия логгов:
    у каждого логгера есть родитель (полное имя логгера задается перечеслением через точку всех родителей), задавая конфигурацию родителя можно выставить опцию, чтобы все дети автоматически получали ее же (log propagation). То есть я могу например создать несколько родительских логеров, задать им обработчики (н-р на уровни ERROR и WARN слать email) и все дети будут использовать их же, но более того если мне нужно заглушить какое то дерево логгов, я просто специализирую конфигурацию для его полного пути. И все это в одном месте и один раз.
  3. Очень разумная подмена стандартной console. Разрешаются пути относительно текущей рабочей директории, что позволяет без проблем конфигурировать вывод console.log и получить плюшки логгера.

После непродолжительно использования (я заметил, что в этом проекте форматированию уделяется столько же мало внимания как и в других), я сделал несколько пулл реквестов, чтобы добавить возможность вывода миллисикунд, поддержку форматированного вывода ошибок, но после непродолжительного общения с автором и 4-5 пулл реквестов, стало очевидно, что автор хочет идти своей дорогой и я форкнул проект добавив, то о чем мечтал.
Поковырявшись в коде я заметил, что автор оптимизировал код для бенчмарка. Свое мнение о таких вещах я лучше оставлю при себе.
Что я изменил в самой либе, оставив не тронутыми обработчики:
  1. Выкинул все такие оптимизации для бенчмарка — писать такое себя не уважать.
  2. Формат сообщений в intel: нужно у полей объекта-записи указывать их тип (н-р ‘[%(date)s] %(name)s:: %(message)s’), но ведь типы этих полей известны — так зачем нужно их указывать. Вместо этого я взял формат сообщений из logback.
  3. Для форматирования аргументов при логгировании используется свой собственный аналог util.format причем со своими ключами и он же используется при подмене консоли, то есть если сторонняя либа напишет, что то в консоль мы получим не то что ожидаем. Естественно это было заменено на util.format
  4. После некоторого профайлинга стало очевидно, что все время уходит на форматирование сообщений. Так как формат обычно задается один раз разумно его оптимизировать, что и было сделано, с помощью new Function формат собирается один раз, а не при каждом вызове.

Есть еще некоторые мелочи, но это будет уже какой то пиар, а не сравнение.
Чтобы показать некоторую пузомерку отличий — маленький замер скорости (код бенчмарка, все версии последние). Просто выведем logger.info(с сообщением):
$ node benchmark/logging.js 
console.info x 1,471,685 ops/sec ±0.79% (95 runs sampled)
rufus.info x 200,641 ops/sec ±1.04% (84 runs sampled)
winston.info x 65,567 ops/sec ±0.80% (96 runs sampled)
intel.info x 56,117 ops/sec ±1.51% (92 runs sampled)
bunyan.info x 86,970 ops/sec ±1.71% (81 runs sampled)
log4js.info x 45,351 ops/sec ±3.25% (79 runs sampled)
Fastest is console.info

При вот таком формате сообщений '[%date] %logger:: %message', который разумно ожидать всегда. Попробуем заменить на стандартное сообщение в intel, чтобы ощутить всю мощь оптимизаций:
$ node benchmark/logging.js 
console.info x 1,569,375 ops/sec ±0.66% (95 runs sampled)
rufus.info x 199,138 ops/sec ±0.81% (97 runs sampled)
winston.info x 66,864 ops/sec ±0.84% (91 runs sampled)
intel.info x 173,483 ops/sec ±5.64% (59 runs sampled)
bunyan.info x 86,357 ops/sec ±1.02% (94 runs sampled)
log4js.info x 49,978 ops/sec ±2.29% (81 runs sampled)
Fastest is console.info

Интересное изменение.
Вообщем, то все. Если кому интересно — форк (я скорее всего не буду принимать feature запросы, так как писал для себя в свободное время, с багами и пулл реквестами добро пожаловать).
Как всегда, надеюсь в комментариях найти что-то новое для себя. Ошибки пожалуйста в личку.
AdBlock has stolen the banner, but banners are not teeth — they will be back

More
Ads

Comments 19

    –1
    Есть еще одна библиотека — debug (npm debug). Ее очень удобно использовать как в процессе написания библиотек, так и для логирования. Она не имеет привычных уровней логирования, вместо этого вводятся id типа логов, кооторые можно гибко включать, используя wildcard.

    var debug = require('debug')('worker');
    
    setInterval(function(){
      debug('doing some work');
    }, 1000);
    


    $ DEBUG=http,worker node server.js
    


    image

    Рекомендую ;)
      0
      Да, знаю про эту вещь, но это не то =)
      0
        0
        Несколько вопросов:
        1. Есть ли разделение логов по датам, т.е. каждый день, час или месяц начинаем писать в новый файл?
        2. Есть ли автоматическое удаление старых файлов (например, храним 100 последних)?
        3. Поддерживается ли запись в лог из нескольких процессов (cluster)?
        4. Реализована ли буферизация записи в лог на уровне таймеров (запись не чаще N мсек.) и на уровне объема буфера (например, пишем в память 128кб и сбрасываем это на диск в свободное время)?
          0
          4. Это забота ядра, двойная буферизация будет лишней. Вряд ли какой-либо из логгеров делает fdatasync, чтобы что-то изменить.
            0
            Тем не менее, у класса stream.Writable в Node.js есть собственные буферы чтения и записи, и мы можем управлять их размерами. Более того, я проводил тесты для CentOS 6.5 (64 бит) и Win 7 (64 бит), в обоих случаях производительность записи в логи существенно поднималась, если увеличить буфер записи, выделенный по-умолчанию с 16 кб до 64 кб, а вот при большем увеличении, существенного увеличения производительности нет.

            Автору библиотеки, btd: при создании файлового потока 1 строчку можно дописать и будет шустрее, см. пример тут.
              0
              Спасибо, возьму на заметку.
            0
            Про intel:
            1. Да
            2. Да
            3. Нет
            4. Нет
            Если говорить как я делаю н-р logrotate
            1. Да
            2. Да
            3. Не думаю что игра стоит свеч чтобы во время исполнения синхронизировать логи от нескольких процессов. Я лично пишу в разные файлы. Если нужно будет собрать я использую коллектор.
            4. Идея понятна, но тут еть несколько моментов: 1. Нода работает в одном процессе, логи пишутся в нем же при краше процесса мы херим логи, 2. В intel используются стримы не думаю что это сложно реализовать на их уровне и просто скормить обработчику собстевенный.
              0
              По пункту 3: два процесса могут писать в один файл, если оба открывают его с флагом «a». Тут только проблема будет в ротейте, создавать новые и удалять старые файлы должен Master процесс, а не Worker, и не несколько процессов сразу, ну и Worker должен открывать файл уже после того, как Master его создает. Вообще это удобно, представьте, что работает 16 или 32 воркера, это сколько же будет лог-файлов плодиться.
                0
                Да, я знаю, что можно писать с нескольких процессов, тут проблема не в возможности, а в результате. Что-то мне кажется, что такой лог будет не очень полезным при чтении.
                  0
                  Тогда еще нужно будет логировать ID процесса и кто он (Master или Worker). Для веб-сервера полезно, например Apache и Nginx не делают же 32 лог-файла если у них в конфиге установить параметр 32 процесса.
            +1
            по поводу таймштампов в винстоне: github.com/flatiron/winston#console-transport
            в settings просто указываем timestamp: true и дело в шляпе:

            image

            мне лично винстон очень нравится тем что я одновременно подключил 2 транспорта: в файл (в json формате) и в консоль (обычным текстом). хотя я много других и не пробовал.
              0
              Спасибо я честно не заметил этих опций чуть позже обновлю пост, чтобы людей в заблуждение не вводить. Подключение нескольких транспортов я бы сказал это одна из минимальных вещей которые должна делать либа для логгирования.
                0
                Как-то невежливо списывать библиотеку со счетов только потому, что её надо настраивать :) Winston действительно неплох.
                  0
                  Дело не в настройке а в возможностях. Да у него много транспортов и по скорости он довольно хорош, но той конфигурации что есть мне не достаточно.
              0
              Соглашусь что для анализа производительности логи в таком виде трудно применимы :) Потому я и занимаюсь портированием Pinba на Node.js и надеюсь на днях написать об этом.
              0

              Only users with full accounts can post comments. Log in, please.