Comments 45
Ух-ты, про неймспейсы не знал, спасибо!
Но сразу напрашивается — а что если нужно писать 2 типа логов в одном приложении (процессе): одни (system log) можно рейтлимитить и пропускать, другие — только логировать на диск (access/audit log)?
Второй вопрос — пробовали ли использовать journal-upload для централизованного сбора?
P.S. Добавлю мои пять копеек в пользу journald/syslog — они работают поверх DGRAM, а не STREAM сокетов. А это значит в приложении не нужно городить синхронизацию — несколько тредов могут писать в сокет независимо друг от друга.
Я не знал про существование journal-upoad, спасибо. Я видел, что там что-то есть "с сетью", но прошёл мимо. У нас нет задачи централизации (никому эти терабайты в день не нужны в одном месте, так что прямо сейчас оно мне "не нужно"), но если возникнет — я пристально посмотрю.
Разные типы рейтлимитов — теоретически, идея интересная, но сейчас я не вижу ничего подобного.
Сегодня я узнал, что AF_UNIX | DGRAM — это не то, что вы думаете, и сообщения не теряются, а троттлят пишущее приложение. Увы.
И что — и никаких tail -f /var/log/messages?
И как зачем теперь жить?
journalctl -f.
В предложенном варианте всё ещё интереснее. У вас остаётся всё как было (например, запись в /var/log/messages), всякий низкошумный вывод редких демонов и т.д.
А шумное приложение (которое генерирует больше мегабайта логов в секунду) тихонько пишет где-то там, не мешая системным логам.
Практическое наблюдение: пока мы не реализовали эту штуку (запись логов в отдельный namespace), мы получали системный журнал, который переполнялся по объёму в течение нескольких часов. messages хранил данные дольше, но ценой невероятно тяжёлой суточной ротации (где проблема и была идентфицирована).
P.S. Для самоубийц своей консоли есть journalctl --namespace myapp -f.
syslog-ng фильтрами и целями отлично решает
syslog-ng делает общий сокет для приёма всего, а потом фильтрует. Дальше у нас классическая проблема "писать всё, тормозить приложение", либо "дропать, но не тормозить приложение", причём "писать" и "дропать" касается всех сразу. Инстансы journald позволяют разнести нагрузку так, что система свой лог ведёт как обычно, а приложение работает с per-application (per-namespace) полиси.
Ещё одна проблема syslog-ng в том, что в получившемся очень трудно разобраться. Если у вас терабайт логов, то прочитать лог "за вчера с 11:00 до 11:01 от сервиса такого-то с приоритетом таким-то" становится сложной задачей. Это, конечно, уже не сбор логов, но если вам такую штуку выдают с самого начала, why not?
А syslog я очень не люблю за MAIL, UUCP и прочие facility, давно сгнившие.
К сожалению, у journald до сих пор есть фатальный недостаток — невозможность фильтрования того что будет записано на основе шаблонов. В итоге если какой-то сервис пишет одно полезное сообщение на миллион бесполезных вся эта муть уходит в журнал, и хорошо ещё если размер позволяет его оттуда вытащить — хотя чаще ротация убивает всё полезное.
В github уже несколько лет висит штуки три тикетов на эту тему, но Поттеринг занял жёсткую позицию "всё должно писаться, фильтры только на просмотре или в самом приложении перед выводом" — и ему абсолютно пофиг на аргументы пользователей.
У journald также отсутствуют гибкие настройки по ротации — т.е. скажем, ротация каждый час, день, день недели, по размеру файла etc, с удалением старья если его больчше чем, или оно старее чем и т.п. — для каждого приложения отдельно, разумеется — увы, это "не задача собирателя журналов".
Всё это делает его весьма непривлекательным кроме базовых вещей — типа посмотреть что происходило в системе последние несколько часов.
Ну, на самом деле, это у нас и есть ключевой сценарий. Когда 'talkative application' что-то ломает, программисты хотят видеть всё, что приложение написало за этот момент (и уговорить их на sampling не удаётся).
Насчёт ротации вы не правы, с использованием namespaces вы можете настроить индивидуальную ротацию для каждого журнала как раз по этим правилам: по размеру, по по старости архива (плюс по наличию свободного места).
Вот пример ротации раз в 68 минут: MaxFileSec=4080. А вот пример удаление старья, которое пролежало больше 8 дней: MaxRetentionSec=691200.
В вашем частном случае — да, нужно всё, но чаще нужно наоборот — избавиться от мусора — в идеале в журнале должно быть пусто если в системе нет проблем или аномалий. Т.е. грубо говоря если кто-то логинится каждую секунду и это норма — то логировать нужно не факт логина а его отсутствие в течение какого-то времени, и т.п.
Namespaces, кстати, были как раз сделаны в качестве костыля в связи с отсутствием нормальных фильтров — но костылями и остались, возможностей много не прибавилось.
А ротация "раз в N минут" это совсем не то же самое что "ротация в 00:00 каждый день" или "ровно в начале каждого часа" (не говоря уже про "каждую среду" или "первый понедельник каждого месяца"), равно как и отсутствие возможности удалять не просто старьё которому больше 8 дней, а делать это в одно и то же время каждый день.
В общем глядя на то как это сделано сейчас создаётся впечатление что сделано лишь бы сказать что оно есть и как-то настраивается, но без излишеств.
Ох, вы прям страшную вещь говорите. Я там был, я там знаю. Не надо так делать.
Журнал должен логгировать то, что происходит. Если кто-то (мониторинг старого образца по ssh на хост) на сервер заходит раз в 30с в течение года, то в журнале должны быть все эти логины. Потому что если вместо мониторинга к вам зайдёт V@sy@ Hazker, то вы хотите иметь всю историю происходящего для последующего security analysis. То же касается и не security, а просто 100500 одновременных логинов, положивших сервер.
Дело журнала — писать.
Дальше, вы хотите по этим данным делать аналитику, и, например, первичную фильтрацию. Делайте, кто ж вам мешает. Но не в момент сохранения журнала.
Алсо, ротация в 00:00 — это то, из-за чего мы проблемой занялись. До перехода на journald каждый демон сам ротировал. У нас было примерно 30 демонов с толстыми логами. Сервер справлялся с записью этих логов, но когда 30 начали одновременно (!) ротировать 30 разных файлов (с компрессией, разумеется), это вызвало поток холодного чтения и полностью затрешило массив на старых дисках (шпинделях).
Так что "ротация в 00:00" это очень сильный антипаттерн, вызывающий несправедливые всплески нагрузки.
Потому что если вместо мониторинга к вам зайдёт V@sy@ Hazker,
Это если он в принципе может зайти на этот хост. А так — у меня во внутренней сетке (которая за забором и колючей проволокой, без выхода в интернет от слова "совсем") в журнале тысячи логинов от одного и того же юзера (по sftp) — которые я там видеть не хочу, ибо важнее знать что он не залогинился чем то что он это сделал, к тому же если уж в эту сетку проберётся чужой — то запись в журнале мне совсем никак уже не поможет.
Что печально, клиент настоял на "стандартных пакетах" — т.е. отключить всё эту дребедень я не могу, а вот искать реально нужные сообщения бывает трудно — за счёт ограниченности ресурсов ротация логов происходит раз в пару дней, а о проблеме могут сообщить через три дня, т.е. если повезёт — я ещё найду то что нужно, но часто не везёт и приходится запускать "journalctl -f | grep ..." и ждать.
Да есть куча софта в котором не настраивается что нужно а что нет — я за последние 10 лет не помню ни одного случай когда мне нужно было хотя бы 5% от того что пишется в журнал, причём точно известно что можно вообще без риска отключить чтобы оно не писалось.
А теперь представьте что это не большой толстый сервер где места вайлом а маленькое (но удаленькое) устройство типа RPi с SD карточкой — куда пишется весь этот мусор. Догадываетесь куда я клоню? У админа просто обязана быть возможность выбирать что и куда писать — потому что часто у него нет возможности решить этот вопрос в источнике, а ресурсы могут быть ограничены.
Так что "ротация в 00:00" это очень сильный антипаттерн, вызывающий несправедливые всплески нагрузки.
Это зависит — у меня это решается тем что компрессия откладывается на после ротации в непиковую нагрузку (с низким приоритетом и последовательно), к тому же она откладывается на минимум один интервал (аналог delaycompress в logrotate).
А вообще всё что я хочу сказать — это то что нормальный журналятор должен давать выбор, а не диктовать условия журналирования — чем, увы, страдает journald. Если мне нужно будет писать всё — я включу это явно, но в 95% случаев мне вообще ничего писать не нужно (а оно пишется — загляните в лог любого десктопа, там сплошной мусор в журнале, который вообще никто не смотрит).
Окей, окей, у вас в инфраструктуре не бывает уязвимостей, а в софте багов. Бывает, бывает. Я вам объяснил принцип, что журналы — это журналы (без модификаций), а анализ по журналам — это уже совсем другой процесс.
У journald есть настройки логгирования, включая частоту flush'а в персистентное хранилище с возможностью его отключить вообще.
Я не понимаю куда вы клоните, скорее, наоборот, вижу, что просто ругаете.
если повезёт — я ещё найду то что нужно, но часто не везёт и приходится запускать «journalctl -f | grep ...» и ждать.А если совсем не повезёт, и окажется, что вы в своём Супер Компактном Журнале Только Важных Событий как раз не логируете то, что вам потребуется для решения какой-то новой проблемы? Писать два лога — полный и «компактный»? Это ж ещё хуже, чем просто полный.
Если мне нужно будет писать всё — я включу это явно, но в 95% случаев мне вообще ничего писать не нужно (а оно пишется
Никто же не заставляет включать log persistence. Пусть пишет себе в рамдрайв, а вы форвардите всё в сислог-демон-по-вкусу и фильтруете там привычными инструментами, раз странного захотелось.
Storage=volatile
ForwardToSyslog=yesДа, это не будет journald-only решением, но зато вполне стандартным в части универсализации сбора логов от приложений — всё, что умеет писать только в stdout/stderr и знать не знает о сокетах, будет так же отправлять свои данные по стандартному маршруту, спасибо, ваши буковки очень важны для нас.
Еще один существенный недостато — journald логи занимают намного больше места чем обычный текстовый
Вы уверены? journald выделяет место 8Мб кусками, так что 100 строк действительно, будут сильно "большими". Чем больше логов в этом файле, тем меньше разница.
Учитывайте ещё метаданные журнала (timestamps, pid процессов и т.д.).
(Я сейчас запустил сравнение на 13Гб журнале из стейджинга, через сколько-то времени отпишу сколько там символов внутри было).
А ещё там есть in-line компрессия.
Уверен, т.к. буквально неск месяцев назад перевел сервера с rsyslogd на journald и внезапно места логи стали занимать в неск. раз больше даже при включенной компресии в journald. Да скорее всего это изза методанных, но толку в них лично для меня мало. Все важное и rsyslog записывае. В итоге вернулся обратно.
Ну и сам процесс journald тёк по памяти.
Насчёт текущей памяти — за несколько лет эксплуатации journald в продакшене (в дефолтном конфиге) я ни разу не видел текущую память у него. Какой размер файла вы делали?
Метаданные journald весьма полезны (и это означает, что приложению их писать уже не надо — ни своё имя, ни pid, ни дату).
У меня с тестов из 13Гб журналов (плохая синтетика на которой проверяли точность ротации) получилось 2Гб short'а и 2.1 short-full. Получается коэфицент 5.9. Посмотрели на начальной инсталляции в продакшене — там сжатие от 64 байт, там коэфицент около 4.
Сравнил с каким-то nginx-ориентированным ELK'ом, там 30 к 6 (т.е. тоже около 5).
В целом, замечание крайне важное, спасибо, я сейчас пост обновлю.
Слушайте, вот как вы с этим живёте, journald же аццки невообразимо тормозит.
Вот допустим смотрим systemctl status $SERVICE. При этом нам попытаются показать 10 последних строк логов. Почему-то для этого, как я замерял, systemctl(?) попытается прочитать ВСЕ файлы journald логов. Даже если их несколько сотен за несколько месяцев. Если при этом они лежат на HDD и отсутствуют в page cache — привет тормоза на десятки секунд прежде чем systemctl status покажет хоть что-нибудь.
С journald аналогично. Нельзя просто взять и посмотреть например journalctl -en 1000 foo.service — это недоразумение попытается прочитать все файлы логов, а не только парочку последних.
Наблюдаю это уже много лет и никаких улучшений не видно.
Когда несколько лет назад пробовал включить сжатие эффект был нулевой кажется. Оно похоже сжимает каждую запись отдельно. Ну что за бред? В моих юз кейсах записи короткие их бессмысленно сжимать по одной, нужно собирать в какой-то минимальный батч хотя бы на несколько килобайт.
Я честно говоря уже отчаялся увидеть улучшения и подумаваю соорудить для админский костыль. Скриптом перемещать сротированные journald файлы на другой volume например с btrfs сжатием. Собрать с помощью какого-нибудь unionfs/aufs директорию общую с содержимым и /var/log/journal и /var/log/btrfs_compressed_journal и если нужно посмотреть логи за долгое время, то вызывать jouranlctl --directory=$UNIONSFS_MERGED_DIR.
Избавлюсь так от тормозов systemctl status и journalctl наверняка будет быстрее отрабатывать если логи не в кеше, ожидаю ускорения на порядок.
Btrfs RIP
Есть такое мнение. При этом сама btrfs постепенно взрослеет, и у меня, например, уже несколько лет на всех разделах, включая системный (кроме media, boot и EFI).
Btrfs was removed from RHEL 8 in May 2019
кажется вот с этого всё началось: lore.kernel.org/linux-btrfs/4C07C321.8010000@redhat.com
Он не читает "все файлы логов", он открывает их индексы. Если вы возьмёте что-то вроде ELK, там будет то же самое.
Сжатие надо включать с правильным размером (не просто 'yes', читайте man journald.conf). Записи жмутся поэлементно для того, чтобы быстро их находить: --grep, --since, --unit и т.д.
В моих замерах по ссылке видно, что после очистки кеша и вызова systemctl status foo.service в кеше оказывается >50% каждого из ротированных файлов логов journald. Какой-то очень неэффективный индекс, если для его использование приходится прочитать больше половины файла.
Замер с --since я тоже делал. И опять-таки видно, что читаются фрагменты из всех файлов. Почему бы не обращать внимание на mtime и вообще не пытаться работать с файлами, в которых заведомо нет нужной информации, потому что они в последний раз изменялись до момента, указанного в --since? В этом journald не сделаны тривиальные оптимизации((
Я сравниваю journald логи не с elk, а с /var/log/everything.log.
И man journald.conf я читал
Compress=
Can take a boolean value. If enabled (the default), data objects that shall be stored in the journal and are larger than the default threshold of 512 bytes are compressed before they are written to the file system.
Не похоже, что указание какого-то числа заставит journald собирать несколько записей в один batch.
В батч нет опции собрать. Жмутся отдельные записи. Насчёт чтения "больше половины индекса" не скажу, возможно, readahead линукса вам "помогает". В моих тестах выборка по индексам (а юнит — это индексированное поле) происходило почти мгновенно, не смотря на журнал >13Гб в размере, полный дамп которого занимал порядка 3-5 минут.
Вы попробуйте сначала вычистить из кеша файлы журнала
find /var/log/journal -type f -exec vmtouch -e {} +
А потом замерить сколько времени занимает выборка хвоста записей по индексу (journalctl -e).
Очень удивительный должен быть эксперимент либо в любом случае. Либо для вас тормозами, либо для меня, если у вас такая комбинация отработает быстро.
Кеш можно дропать более простым методом
echo 3 > /proc/sys/vm/drop_caches
time journalctl -e --namespace myapp -n 100 --no-pager
real 0m2.272s
user 0m0.083s
sys 0m0.728s
du -h /var/log/journal/69397f53c7c94185890ca49accd8b6f9.myapp/
21G /var/log/journal/69397f53c7c94185890ca49accd8b6f9.myapp//proc/sys/vm/drop_caches сбрасывает вообще всё, так что менее показательный последующий замер получается. Вдруг на чтении чего-нибудь из /usr последующая команда тормозит? Кроме того vmtouch работает без прав рута, в отличие от записи в /proc/sys/vm/drop_caches
$ time journalctl -eu co2mon >/dev/null
real 0m11,320s
user 0m0,044s
sys 0m0,188s
$ du -sh /var/log/journal
2,7G /var/log/journalВаши 2 секунды конечно не так вопиющи. Подозреваю идеальные условия: хороший raid, отсутствие фрагментации, большой *MaxFileSize (у меня 16M).
Но даже 2 секунды как-то много для задачи, для выполнения которой по идее достаточно прочитать хвост <1MB из одного файла.
У нас MaxFileSize 2Гб. Мы готовились к толстому логу и получили его (журнал 20Гб). С той стороны у нас обычная виртуалка на "чём попало", потому что это инсталляция для тестовых машин.
Чтение индексов должно проходить полностью, это константа (o(1)) для того, чтобы остальные запросы выполнялись быстро. Например, я на этом логе могу попросить вот так вот (после сброса кешей):
time journalctl --namespace myapp --since -10h --until -9h -u unit -n 20 --no-pager
real 0m1.120s
user 0m0.007s
sys 0m0.195sБез индексов на 20Гб архиве логов это займёт… ну вы поняли.
Я вынес из этой дискуссии для себя ценную мысль попробовать сильно увеличить MaxFileSize и посмотреть что выйдет. Спасибо.
Это хорошо, что индексы ускоряют некоторые операции. Но в моих сценариях, в котороых большинство запросов — посмотреть, что произошло совсем недавно, я наблюдаю тормоза. Вот ещё сделал пару замеров сейчас, со сброшенными кешами.
$ time journalctl --system -en 10 -u '*backup*.service' >/dev/null
real 2m18,119s
user 0m0,428s
sys 0m2,559s
# Funny! tar -c >/dev/null finishes instantly
$ time tar -c /var/log/journal/ | cat >/dev/null
tar: Removing leading `/' from member names
real 0m42,242s
user 0m0,674s
sys 0m5,308sЗапрос на последние несколько событий занимает в 3 раза больше времени, чем нужно целиком прочесть все файлы логов.
Мне не удаётся воспроизвести ничего подобного. Сейчас даже проверил на продакшене (где уже java фигачит в 2000% CPU, генерируя свои десятки гигабайт логов) — всё мгновенно, или с задержками в единицы секунд.
Возможно, на spinning rust всё иначе, но требовать от софта оптимизировать sequential read в 2021… скепсис.
При увеличении MaxFileSize 16MiB → 64MiB стало только медленнее.
Зато очень помогло поиграться с readahead. От увеличения значения по-умолчанию 128 KiB до 2048 KiB стало вчетверо быстрее!
В общем я перенёс у себя /var/log/journal на сжатый btrfs раздел. Эффект супер! Теперь тот же тестовый запрос, что раньше выполнялся >2минут выполняется секунд 10-12. Кайф!
Пришлось только настроить выполнение btrfs filesystem defragment -r -czstd /var/log/journal после ротации логов.
journald вместо syslog