В ротейт мне логи! Про минимализм, busybox и логирование.
Так как я довольно много пишу на шелле, передо мной уже довольно давно встала проблема логирования в скриптах. После просмотра километровых логов начинает рябить в глазах, сложно выделить важные моменты при быстром скроллинге, например, какой-нибудь warning или внезапный error. Одним словом, терпение закончилось и я решил написать свой велосипед, по возможности функциональный, лёгкий и с минимумом зависимостей - всё, как я люблю. 
Традиционный список хотелок:
- Минимальные зависимостии размер
- Уровни логирования (debug/info/warinig)
- Отключаемая подсветка разными цветами разных типов событий
- Работоспособность под OpenWRT, Android, Alpine и т.п.
- Возможность переопределять параметры переменными в основном скрипте
- Возможность передать в FATAL сразу код завершения
- Настраиваемый формат даты
- Разделитель (очень полезно для отделения частей лога)
- Краткий синтаксис вызова (не люблю длинные имена модулей)
Смысловая нагрузка уровней логирования
Тут всё довольно просто. Это основная функция, ради котрой стоило создавать этот велосипед вместо того, чтобы пользоваться обычным echo "Здесь был Вася". Есть несколько уровней логирования, описанных выше. Приоритет уровней в порядке следования. То есть, если мы выставляем в основном скрипте LOGLEVEL='debug', то будем видеть все сообщения, если LOGLEVEL='info', то всё, кроме DEBUG, если LOGLEVEL='warning' - то увидим только WARNING, ERROR и FATAL и т.д.. Тут всё достаточно стандартно, как во множестве других библиотек подобного назначения в языках высокого уровня. Функционально отличается только FATAL. Смысловая нагрузка следующая:
- DEBUG: то, что мы видим только при отладке, вспомогательная информация, обычно отключается после отладки
- INFO: обычная информация, например, о запуске того или иного процесса
- NOTICE: то же, что и в предыдущем пункте, но отличается статусом и цветом, для выделения более важных сообщений
- WARNING: что-то пошло не так, возможны несущественные негативные последствия, работа продолжается
- ERROR: случилось что-то плохое, это серьёзно, дальнейшая логика действий может быть изменена
- FATAL: шеф, всё пропало, все умерли
Зависимости и с чем едят busybox
Далее пару слов о зависимостях и работе на OpenWRT, Alpine и тому подобном. Фактически оба эти пункта для меня говорят о том, что мы должны использовать по возможности только тот функционал, который предоставляет busybox. Если кто-то не в курсе, то busybox - это бинарный исполняемый файл, который включает в себя функционал множества GPU утилит, необходимых для построения рабочего окружения. То есть и шелл интерпретатор и всякие sed, grep, awk и утилиты работы с сетью, разделами диска и многое другое - всё это содержит внутри busybox, который занимает обычно около 700 - 900 килобайт. Если сделать симлинк на busybox с именем ping, то он будет работать как ping, если с именем netstat - то как netstat. И таких апплетов (в терминологии busybox это называется апплетом) внутри обычно от сотни с небольшим до более, чем двух сотен, так что вполне есть, где разгуляться и с помощью чего описывать логику. Да фактически, при помощи функционала busybox можно делать с системой всё, что взбредёт в голову. Это позволило сделать множество устройств с мизерным количеством флеш памяти на борту (например, два мегабайта), внутри которых бежит линукс. Минимальный образ Alpine Linux для контейнеров более, чем наполовину состоит из busybox. Если воспринимать software как тип искусства, то busybox - это однозначно шедевр мирового уровня, которым я откровенно восхищаюсь. У вас есть дома роутер? Ну вот, в 99% случаев внутри busybox. На работе стоит SIP телефон? Ну, вы уже поняли. Поэтому всё, что я пишу, я стараюсь писать используя только /bin/sh вместо /bin/bash хотя бы уже потому, что в отличие от bash, sh есть везде (для многих это почему-то является откровением). Во FreeBSD, например, по умолчанию установлен csh и скрипты, начинающиеся с #!/bin/bash просто не смогут запуститься без изменения кода.
Прочие мелочи
Про формат даты по-моему, очевидно, тут ничего объяснять не нужно. Подсветка синтаксиса - тоже. WARNING и ERROR просто обязаны бросаться в глаза, когда ты быстро пролистываешь вывод, используя PageDown. К выводу о том, что разделитель тоже нужен и важен, я пришёл со временем. Это так же удобно при поиске в больших логах - сразу видно, где у тебя закончилась обработка одного логического блока и началась обработка другого.
Синтаксис
Теперь про синтаксис вызова. Так как скрипты зачастую пишутся или редактируются на удалённой машине через ssh, а то и скорую руку с телефона, то нужно рассчитывать на то, что пишем мы их не в развесистой среде разработки с автодополнением, подсветкой синтаксиса и прочими прелестями жизни, а сурово в каком-нибудь vi (даже порою не vim, если это роутер например). Следовательно, набирать что-то вроде logging.info("blah-blah-blah") будет излишне утомительным. Поэтому синтаксис вызова я сократил до минимума. Далее будет пример использования в скрипте с комментариями.
Установка
Всё выложено на github, соответственно, можно оттуда склонировать, но если нужен только файл, то проще всего его взять через raw с того же гитхаба:
wget https://raw.githubusercontent.com/alive-corpse/eslogger/master/esloggerПример использования
#!/bin/sh
# Для начала убедимся, что мы будем инклудить всё из той же директории.
# Поэтому сначала переходим в директорию, откуда был запущен наш скрипт.
cd `dirname "$0"`
# Предположим, скрипт лежит в той же директории. Нужно его подгрузить.
. ./eslogger
# Теперь задаём переменные, отвечающие за отображение логов.
# Оставляем возможность при необходимости задавать переменные не изменяя
# код скрипта. Вызов может выглядеть так: LOGLEVEL=info ./test.sh
# При обычном вызове ./test.sh в нашем случае будет уровень debug.
# Следующую строку можно пропустить, если вас устраивает уровень info.
[ -z "$LOGLEVEL" ] && LOGLEVEL='debug'
# Аналогичным образом задаём формат даты.
[ -z "$LPREF" ] && LPREF='date +%Y.%m.%d-%H:%M:%S'
# Если в нашей системе отсутствует бинарник tput, который позволяет
# получить количество строк и столбцов экрана, задаём ширину
DEFAULT_COLS=70
# Включаем или выключаем подсветку синтаксиса (0/1 соответственно)
[ -z "$LCOLOR" ] && LCOLOR=1
# А теперь выводим все типы записей и разделитель:
d # Это как раз разелитель
l d "This is debug message"
l i "This is info message"
# Если не указывать тип сообщения, то по умолчанию будет тип info
l "This is also info message"
l n "This is notice message"
l w "This is warning message"
l e "This is error message"
l f "This is fatal message"
# Если fatal error был последним и в этом месте нам нужно завершить скрипт
# с неким кодом возврата, нужно использовать тип fe и тогда код возврата
# Можно будет передать третьим параметром. Если код не передавать, скрипт
# завершится с кодом 1. После вывода основного сообщения о фатале будет
# Выведено дополнительное, сообщающее о том, что все будущие операции
# отменены.
l fe "This is fatal message with exit code" 127
Результат выполнения скрипта можно увидеть на скриншоте в начале статьи.
Теги: logging, shell, busybox, minimalism