19. Логирование, модули debug и winston

Наша следующая тема логирование или иначе говоря отладочный вывод. Когда проект маленький, то вполне достаточно console.log для того, чтобы что-то вывести. Однако проект имеет свойство расти. Например, тот же server.js естественным образом разделяется на сервер и обработчик запроса — request. Со временем появляется работа с пользователем, база данных и так далее. Каждый файл может захотеть по ходу своего выполнения, что-то вывести. И этот вывод для нас очень важен, поскольку показывает, что происходит. Особенно, если что-то происходить не так. В текущем коде, везде используется console.log для вывода

Это означает, что перейдя по браузерному url, я получу однообразную кашу из всех записей, что делает скрипт.

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

Для этого используются специализированные модули. Рекордсмен по простоте, это модуль DEBUG.

Модуль debug

Давайте поставим его в наш проект. Для этого вспоминаем главу — 7. Введение в NPM — менеджер пакетов для Node.JS и в консоле, из директории проекта, вводим команду

получаем

screenshot_19_01

как видим NPM создал, как в общем то и ожидалось, директорию «node_modules» в корне нашего проекта

screenshot_19_02

куда и поставил новый модуль, «debug». Давайте теперь подключим его, добавив такую строку

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

Вот так, в данном случае, пусть это буде ‘server’. Теперь вместо console.log мы пишем debug

Аналогичную операцию я произвожу и с файлом request.js, только на этот раз идентификатором будет не ‘server’ a ‘server:request’. Обратим внимание на двоеточие в  ‘server:request’, это нам еще будет важно

Итак, запускаю, сейчас не из WebStorm а через терминал

screenshot_19_03

И мы видим, что ничего не выводит, потому что, чтоб  выводило, мне нужно указать, что выводить. Для возврата в исходный режим нажимаем сочетание клавиш «Ctrl + C». И пробуем еще раз, но теперь для передачи информации о том, что выводить, нужно создать переменную окружения с названием «DEBUG» и дать ей значение, для начала, «server»

screenshot_19_04

На эту тему, для пользователей windows, есть интересная статья —

Команда SET — работа с переменными среды Windows

Что произошло? Мы создали переменную которой дали значение, запустили сервер и видим что в консоль дебагом выведено сообщение  которое помечено идентификатором «server».

 

У нас ведь есть еще один файл, который тоже должен выводить, нужную нам, информацию в консоль. Но в фале request.js другой идентификатор, а именно — ‘server:request’, давайте добавим его в нашу переменную. Вводим в консоле

Давайте чуть отвлечемся и проговорим вот такой момент, который сейчас важен. Переменная «DEBUG» имеет значение, это мы уже поняли. Это значение это строка. И если до последней команды в консоле, эта строка была равна «DEBUG=server», то после она стала равной  «DEBUG=server:request,server». Как видим последней командой мы дописали значение в начало этой строки.

От сюда делаем два вывода —

  • во первых принципиально важно не забыть поставить запятую после выражения которое мы хотим добавить к нашей строке, потому что именно по запятым парсится значение переменной DEBUG, и отделяя запятыми мы перечисляем идентификаторы которыми помечены интересующие нас логи, прямо как точка с запятой — «;» в переменной «PATH».
  • во вторых если у нас вдруг появится файл «user.js» и в нем мы подключим модуль «debug» которому укажем идентификатор, скажем, «user», то нам нужно будет опять проделать такую операцию

    если мы хотим выводить логи из этого файла.

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

Просто set и имя переменной, вот такая многогранная команда «set».

И так возвращаемся к нашему серверу. Мы добавили значение в переменную DEBUG

screenshot_19_06

теперь посмотрим какое значение имеет переменная DEBUG

screenshot_19_07

Судя по значению должно выводить логи из обоих файлов, проверим

screenshot_19_08

запустили сервер и он сразу вывел лог помеченный идентификатором ‘server’. Теперь перезагрузим открытую в браузере страницу по адресу — «http://127.0.0.1:1337/echo?message=TEST«, смотрим в консоль

вот и второй файл и логи в нем отработали.

К стати если мы уже решили выводить абсолютно все логи, то можно значение переменной  DEBUG установить равной «*». Давайте установим, убедимся чему равно и запустим сервер. И не забываем, чтоб прервать работу сервера из консоли, достаточно нажать сочетание клавиш «Ctrl + C». Итак смотрим

screenshot_19_10

Теперь перезагрузим открытую в браузере страницу по адресу — «http://127.0.0.1:1337/echo?message=TEST» и смотрим в консоль

Все работает по прежнему.

Модуль winston

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

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

может быть неважной. Эта информация может быть очень важной

поскольку, это ошибка — url не найден.

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

Ставим его

screenshot_19_12

и заменяем в коде require(‘debug’) на require(‘winston’), который возвращает объект «log».

Для того чтобы логировать, я должен вызвать соответствующий метод этого объекта

  • log.debug — Маленькой важности
  • log.info — Сообщение средней важности.
  • log.error — это ошибка.

Все ошибки считаются очень важными, кроме того логгер настроен так, что по умолчанию он выводит сообщения только уровня info и более важные. Сейчас мы это увидим, запускаю в WebStorm и в браузере перехожу на соответствующий url — «http://127.0.0.1:1337/echo?message=TEST«.

screenshot_19_13

Как и говорилось ранее log.debug вообще не выводится, выводятся только сообщения уровня info и более важные, такие как error.

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

 

Просто сделать обертку над winston, которая будет находиться в отдельном модуле и добавлять интересующею нас функциональность. Назовем этот модуль «log», он будет принимать текущий объект модуля  и возвращать по сути тот же winston, но по разному настроенный, в зависимости от того какой именно модуль мы ему передаем, для каких то будем логировать так, для каких то можно логировать по другому. Вот пример такого модуля

Он экспортирует функцию, которая принимает модуль для которого нужно сделать логирование и возвращает winston настроенный соответственно его пути

В данном случае настройка заключается в том, что мы смотрим на что заканчивается путь и если это «/request.js» то возвращаем winston настроенный одним способом

а если это что-то другое то другим

Для настройки winston здесь используется концепция транспортов. Транспорт это нечто, что умеет передавать информацию, в данном случае информацию из логов. Например есть встроенный в winston транспорт «Console»

Который можно настраивать вот так, указать timestamp, расцветить — colorize, level — использовать его только для сообщений уровня info и выше.

Второй транспорт здесь это файл

который записывает логи, как указано, в файл с названием ‘debug.log’ —  filename: ‘debug.log’ и будет включаться для сообщений уровня debug и выше — level: ‘debug’. То есть фактически для всех. Таким образом, если путь оканчивается на /request.js, то мы возвращаем winston

который будет записывать в консоль сообщения info или выше и в файл вообще все.

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

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

Проверяю это, запустив сервер и перейдя в браузере по адресу — «http://127.0.0.1:1337/echo?message=log-me-please» и мы видим

screenshot_19_14

что действительно информация info, попала в консоль, а так же появился файл debug.log, в котором есть все, все сообщения.

Итак мы с вами рассмотрели отладку,

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

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

NODE_DEBUG

Следующие средство отладки которое мы сейчас изучим называется NODE_DEBUG=»cluster fs http module net timer tls». NODE_DEBUG это переменная окружения которая используется внутри Node.JS. Есть ряд встроенных модулей которые, если эта переменная стоит, могут показывать, что происходит внутри них. Таким образом NODE_DEBUG, это средство для глубокой отладки. Его используют в тех случаях, когда наши возможности по отладке исчерпаны и нам ничего не остается, кроме как заглянуть внутрь самой ноды и посмотреть, что же там делается внутри.

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

на этот раз разделяем, значения присваиваемые переменной NODE_DEBUG, пробелами. И запускаем наш server.js. Для MacOs это будет выглядеть вот так

в этом случае, мы полностью поймем, что внутри сети здесь творится.

Смотрите, я только запустил, не успел никуда зайти, а уже начала поступать информация модуль NET вывел, что мы теперь слушаем все интерфейсы и порт 1337. А теперь перейду по адресу «http://127.0.0.1:1337/echo?message=TEST»

screenshot_19_16

и как видите, я получаю полный отчет, о том, что происходит.

Итак, у нас есть три инструмента логирования, которых хватит как для отладки небольшого проекта, так для полноценного логгинг-решения, ну и на конец, чтобы заглянуть внутрь Node.JS.

 

2 thoughts on “19. Логирование, модули debug и winston”

  1. — К стати проверить
    — И так возвращаемся
    — по прежнему
    — для каких то
    — во первых
    Про запятые уж не говорим: стоят там, где не нужно, отсутствуют там, где необходимы.
    Горе!

  2. В самом первом блоке кода ошибка
    server.on(‘request’, requre(‘./request’));
    requIre

Обсуждение закрыто.