Cбор логов с rsyslog, именами файлов в тегах, многострочными сообщениями и отказоустойчивостью

    image


    Изображение с сайта oxygen-icons.org


    Задача


    Передавать лог-файлы на центральный сервер:


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

    Условия: в инфраструктуре используются только Linux-сервера.



    Выбор софта


    Зачем вообще нужен syslog-сервер, когда есть elastic beats, logstash, systemd-journal-remote и ещё много новых блестящих технологий?


    • Это стандарт для ведения логов в POSIX-совместимых системах.
      Некоторый софт, например haproxy, использует только его. То есть совсем избавится от syslog вам всё равно не удастся
    • Его использует сетевое железо
    • Сложнее в настройке, но богаче по возможностям, чем альтернативные решения.
      Например, Elastic Filebeat до сих пор не умеет inotify.
    • Нетребователен к памяти. Возможно использование на embedded системах после небольшого тюнинга.
    • Позволяет изменять сообщение перед сохранением/пересылкой.
      Странная задача, но иногда требуется. Например, PCI DSS в разделе 3.4 требует маскировать или шифровать номера карт, если они сохраняются на диск. Тонкость в том, что если кто-то ввёл номер карты в строку поиска или в форму обратной связи, то как только вы сохранили запрос в лог, вы нарушаете стандарт.

    Наблюдение: пользователи пытаются ввести номер карты в любое поле ввода на странице, и норовят сообщить его саппорту вместе с CVV.


    Формат сообщений и legacy


    TLDR: всё плохо

    Syslog появился в 80-х, и быстро стал стандартом логирования для Unix-like систем и сетевого оборудования. Стандарта не было, все писали по принципу совместимости с существующим софтом. В 2001 IETF описал текущее положение вещей в RFC 3164(статус "informational"). Т. к. реализации очень отличаются, то в частности в этом документе сказано "содержание любого IP пакета отправленного на UDP порт 514 должно рассматриваться как сообщение syslog". Потом попробовали стандартизировать формат в RFC 3195, но документ получился неудачным, для него в данный момент нету ни одной живой реализации. В 2009 приняли RFC 5424, определяющий структурированные сообщения, но этим редко кто пользуется.


    Вот тут можно прочитать, что обо всём этом думает автор rsyslog Рейнер Герхард(Rainer Gerhards). Фактически, по-прежнему все реализуют syslog как попало, и задача интерпретировать всё это разнообразие ложиться на syslog-сервер. Например, в rsyslog включен специальный модуль для разбора формата, используемого CISCO IOS, ну и для самых плохих случаев начиная с пятой версии можно определять собственные парсеры.


    Сообщения syslog при передаче по сети выглядят примерно так:


    <PRI> TIMESTAMP HOST TAG MSG

    • PRI — Priority. Вычисляется как facility * 8 + severity.
      • Facility(категория) принимает значения от 0 до 23, им соответствуют различные категории системных служб: 0 — kernel, 2 — mail, 7 — news. Последние 8 — от local0 до local7 — определены для служб, не попадающих в предопределённые категории. Полный список.
      • Severity(важность) принимает значения от 0(emergency, самая высокая) до 7(debug, самая низкая). Полный список.
    • TIMESTAMP — время, обычно в формате "Feb 6 18:45:01". Согласно RFC 3164, может записываться в формате времени ISO 8601: "2017-02-06T18:45:01.519832+03:00" с большей точностью и с учётом используемой временной зоны.
    • HOST — имя хоста, сгенерировавшего сообщение
    • TAG — содержит имя программы, сгенерировавшей сообщение. Не более 32 алфавитно-цифровых символов, хотя по факту многие реализации позволяют больше. Любой не-алфавитноцифровой символ заканчивает TAG и начинает MSG, обычно используется двоеточие. Иногда в квадратных скобках содержит номер сгенерировавшего сообщение процесса. Т. к. [ ] — не алфавитно-цифровые символы, то номер процесса вместе с ними должен считаться частью сообщения. Но обычно все реализации считают это частью тега, считая сообщением всё после символов ": "
    • MSG — сообщение. Из-за неопределённости с тем, где же кончается тег и начинается сообщение, в начало может добавляться пробел. Не может содержать символов перевода строки: они являются разделителями фреймов, и начнут новое сообщение. Способы всё же переслать мгногострочное сообщение:
      • экранирование. Получим на стороне приёмника текст с #012 вместо переводов строки
      • использование octet-counted TCP Framing, как определено в RFC 5425 для TLS-enabled syslog. Нестандарт, только некоторые реализации.

    Альтернатива протоколу syslog: RELP


    Если сообщения пересылаются между хостами, использующими rsyslog, можно вместо plain TCP sysog использовать RELP — Reliable Event Logging Protocol. Был создан для rsyslog, сейчас поддерживается и некоторыми другими системами. В частности, его понимают Logstash и Graylog. Для транспорта использует TCP. Может опционально шифровать сообщения с помощью TLS. Надёжнее plain TCP syslog, не теряет сообщения при разрыве соединения. Решает проблему с многострочными сообщениями.


    Конфигурация rsyslog


    В отличии от второй распространённой альтернативы, syslog-ng, rsyslog совместим с конфигами исторического syslogd:


    auth,authpriv.*            /var/log/auth.log
    *.*;auth,authpriv.none     /var/log/syslog
    *.*       @syslog.example.net

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


    $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
    $WorkDirectory /var/spool/rsyslog
    $IncludeConfig /etc/rsyslog.d/*.conf

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


    Т. к. всё это делалось постепенно и с учётом совместимости со старыми конфигами, то в итоге получилась пара неприятных моментов:


    • некоторые плагины(я пока с такими не сталкивался) могут не поддерживать новый RainerScript стиль настроек, им по-прежнему нужны старые директивы
    • настройка через старые директивы не всегда работает как ожидается для нового формата:
      • если модуль omfile вызывается с помощью старого формата:
        auth,authpriv.* /var/log/auth.log, то владелец и разрешения получившегося файла регулируются старыми директивами $FileOwner, $FileGroup, $FileCreateMode. А вот если он вызывается с помощью action(type="omfile" ...), то эти директивы игнорируются, и надо настраивать параметы action или задавать при загрузке модуля
      • Директивы вида $ActionQueueXXX настраивают только ту очередь, которая будет использована в первом action после них, потом значения сбрасываются.
    • точки с запятой где-то запрещены, а где-то наоборот обязательны(второе реже)

    Чтобы не спотыкаться об эти тонкости(да, в документации они описаны, но кто же её целиком читает?), стоит следовать простым правилам:


    • для маленьких простых конфигов использовать старый формат:
      :programname, startswith, "haproxy" /var/log/haproxy.log
    • для сложной обработки сообщений и для тонкой настройки Actions всегда использовать RainerScript, не трогая legacy директивы вида $DoSomething

    Подробнее про формат конфига здесь.


    Обработка сообщений


    • Все сообщения приходят из Input(их может быть много) и попадают на обработку в привязанный к нему RuleSet. Если это явно не задано, то сообщения попадут в RuleSet по-умолчанию. Все директивы обработки сообщений, не вынесенные в отдельные RuleSet-блоки, относятся именно к нему. В частности, к нему относятся все директивы из традиционного формата конфигов:
      local7.* /var/log/myapp/my.log
    • к Input привязан список парсеров для разбора сообщения. Если явно не задано, будет использоваться список парсеров для разбора традиционного формата syslog
    • Парсер выделяет из сообщения свойства. Самые используемые:
      • $msg — сообщение
      • $rawmsg — сообщение целиком до обработки парсером
      • $fromhost, $fromhost-ip — DNS имя и IP адрес хоста-отправителя
      • $syslogfacility, $syslogfacility-text — facility в числовой и текстовой форме
      • $syslogseverity, $syslogseverity-text — то же для severity
      • $timereported — время из сообщения
      • $syslogtag — поле TAG
      • $programname — поле TAG с отрезанным id процесса: named[12345] -> named
      • весь список можно посмотреть тут
    • RuleSet содержит список правил, правило состоит из фильтра и привязанных к нему одного или нескольких Actions
    • Фильтры — логические выражения, с использованием свойств сообщения. Подробнее про фильтры
    • Правила применяются последовательно к сообщению, попавшему в RuleSet, на первом сработавшем правиле сообщение не останавливается
    • Чтобы остановить обработку сообщения, можно использовать специальное discard action: stop или ~ в легаси-формате.
    • Внутри Action часто используются шаблоны. Шаблоны позволяют генерировать данные для передачи в Action из свойств сообщения, например, формат сообщения для передачи по сети или имя файла для записи. Подробнее про шаблоны
    • Как правило, Action использует модуль вывода("om...") или модуль изменения сообщения("mm..."). Вот некоторые из них:

    Подробнее про порядок обработки сообщений


    Примеры конфигурации


    Записываем все сообщения категорий auth и authpriv в файл /var/log/auth.log, и продолжаем их обработку:


    # legacy
    auth,authpriv.*  /var/log/auth.log
    # новый формат
    if ( $syslogfacility-text == "auth" or $syslogfacility-text == "authpriv" ) then {
        action(type="omfile" file="/var/log/auth.log")
    }

    Все сообщения с именем программы, начинающимся с "haproxy", записываем в файл /var/log/haproxy.log, не сбрасывая буфер на диск после записи каждого сообщения, и прекращаем дальнейшую обработку:


    # legacy (обратите внимание на минус перед именем файла, отключающий сброс буфера)
    :programname, startswith, "haproxy", -/var/log/haproxy.log
    & ~
    # новый формат
    if ( $programname startswith "haproxy" ) then {
        action(type="omfile" file="/var/log/haproxy.log" flushOnTXEnd="off")
        stop
    }
    # можно совмещать
    if $programname startswith "haproxy" then -/var/log/haproxy.log
    &~

    Проверка конфига: rsyslogd -N 1. Больше примеров конфигурации: раз, два.


    Клиент: пересылка логов с сохранением имени файла


    Сохранять имена файлов мы будем в поле TAG. В имена хочется включить каталоги, чтобы не наблюдать одноуровневую россыпь файлов: haproxy/error.log. Если лог читается не из файла, а из переданных в syslog сообщений от программы, то она может не согласиться записывать в TAG символ /, потому что это не соответствует стандарту. Поэтому мы закодируем их двойными подчеркиваниями, а на лог-сервере распарсим обратно.


    Создадим шаблон для передачи логов по сети. Мы хотим передавать сообщения с тегами длиннее 32 символов(у нас длинные названия логов), и передавать более точную, чем стандартную, метку времени с указанием временной зоны. Кроме того, к названию лог-файла будет добавлена локальная переменная $.suffix, позже станет понятно, зачем. Локальные переменные в RainerScript начинаются с точки. Если переменная не определена, она раскроется в пустую строку.


    template (name="LongTagForwardFormat" type="string"
    string="<%PRI%>%TIMESTAMP:::date-rfc3339% %HOSTNAME% %syslogtag%%$.suffix%%msg:::sp-if-no-1st-sp%%msg%")

    Теперь создадим RuleSet, который будут использоваться для передачи логов по сети. Его можно будет присоединять к Input, читающим файлы, или вызывать как функцию. Да, rsyslog позволяет вызвать один RuleSet из другого. Для использования RELP надо сначала загрузить соответствующий модуль.


    # http://www.rsyslog.com/doc/relp.html
    module(load="omrelp")
    
    ruleset(name="sendToLogserver") {
        action(type="omrelp" Target="syslog.example.net" Port="20514" Template="LongTagForwardFormat")
    }

    Теперь создадим Input, читающий лог-файл, и присоединим к нему этот RuleSet.


    input(type="imfile"
        File="/var/log/myapp/my.log"
        Tag="myapp/my.log"
        Ruleset="sendToLogserver")

    Стоит обратить внимание, что для каждого считываемого файла rsyslog создаёт state-файлы в своём рабочем каталоге(задаётся директивой $WorkDirectory). Если rsyslog не может создавать там файлы, то весь лог-файл будет заново передаваться после перезапуска rsyslog.


    В случае, если какое-то приложение пишет в общий syslog с определённым тегом, и мы хотим как сохранять это в файл, так и пересылать по сети:


    # Template to output only message
    template(name="OnlyMsg" type="string" string="%msg:::drop-last-lf%\n")
    
    if( $syslogtag == 'nginx__access:')  then {
        # write to file
        action(type="omfile" file="/var/log/nginx/access" template="OnlyMsg")
        # forward over network
        call sendToLogserver
        stop
    }

    Последний stop нужен, чтобы прекратить обрабатывать эти сообщения, иначе они попадут в общий syslog. Кстати, если приложение умеет выбирать другой unix socket для syslog, кроме стандартного /dev/log(nginx и haproxy так умеют), то можно с помощью модуля imuxsock сделать для этого сокета отдельный Input и прицепить к нему нужный RuleSet, не разбирая логи из общего потока по тегам.


    Чтение лог-файлов, заданных через wildcard


    Интерлюдия


    Программист: Не могу найти на лог-сервере логи somevendor.log за начало прошлого месяца, посмотри плиз.
    Девопс: Эээ… а мы разве пишем такие логи? Предупреждать же надо. Ну в любом случае всё старше недели логротейт потёр, если мы его не сохраняли — значит уже нету.
    Программист: бурно возмущается


    Если приложение пишет много разных логов, и иногда появляются новые, то обновлять конфиги каждый раз неудобно. Хочется это автоматизировать. Модуль imfile умеет считывать файлы, заданные вайлдкардом, и сохранять в мета-данных сообщения путь к файлу. Правда, путь сохраняется полный, а нам нужен только последний компонент, который оттуда придётся добыть. Кстати, тут нам и пригодится переменная $.suffix


    input(type="imfile"
        File="/srv/myapp/logs/*.log"
        Tag="myapp__"
        Ruleset="myapp_logs"
        addMetadata="on")
    
    ruleset(name="myapp_logs") {
        # http://www.rsyslog.com/doc/v8-stable/rainerscript/functions.html
        # re_extract(expr, re, match, submatch, no-found)
        set $.suffix=re_extract($!metadata!filename, "(.*)/([^/]*)", 0, 2, "all.log");
        call sendToLogserver
    }

    Вайлдкарды поддерживаются только в режиме работы imfile inotify(это режим по-умолчанию). Начиная с верcии 8.25.0, вайлдкарды поддерживаются как в имени файла, так и пути: /var/log//.log.


    Многострочные сообщения


    Для работы с лог-файлами, содержащими многострочные сообщения, модуль imfile предлагает три варианта:


    • readMode=1 — сообщения разделены пустой строкой
    • readMode=2 — новые сообщения начинаются с начала строки, продолжение сообщения идёт с отступом. Часто так выглядят стектрейсы
    • startmsg.regex — определять начало нового сообщения по regexp(POSIX Extended)

    Первые два варианта имеют проблемы в режиме работы inotify, и при необходимости третий легко их заменяет с соответствующим regexp. Считывание многострочных логов имеет одну тонкость. Обычно признак нового сообщения находится в его начале, и мы не можем быть уверены, что программа закончила писать прошлое сообщение, пока не началось следующее. Из-за этого последнее сообщение может никогда не передаваться. Чтобы этого избежать, мы задаём readTimeout, по истечении которого сообщение считается законченным и будет передано.


    input(type="imfile"
        File="/var/log/mysql/mysql-slow.log"
        # http://blog.gerhards.net/2013/09/imfile-multi-line-messages.html
        startmsg.regex="^# Time: [0-9]{6}"
        readTimeout="2"
        # no need to escape new line for RELP
        escapeLF="off"
        Tag=" mysql__slow.log"
        Ruleset="sendToLogserver")

    Сервер


    На сервере надо принять переданные логи и разложить их по каталогам, в соответствии с IP передающего хоста и временем получения: /srv/log/192.168.0.1/2017-02-06/myapp/my.log. Для того, чтобы задать имя лог-файла в зависимости от содержания сообщения, мы также можем использовать шаблоны. Переменную $.logpath нужно будет задать внутри RuleSet перед использованием шаблона.


    template(name="RemoteLogSavePath" type="list") {
        constant(value="/srv/log/")
        property(name="fromhost-ip")
        constant(value="/")
        property(name="timegenerated" dateFormat="year")
        constant(value="-")
        property(name="timegenerated" dateFormat="month")
        constant(value="-")
        property(name="timegenerated" dateFormat="day")
        constant(value="/")
        property(name="$.logpath" )
    }

    Загрузим нужные модули и выключим $EscapeControlCharactersOnReceive, иначе в принятых логах все переводы строки заменятся на \n


    # Accept RELP messages from network
    module(load="imrelp")
    input(type="imrelp" port="20514" ruleset="RemoteLogProcess")
    
    # Default parameters for file output. Old-style global settings are not working with new-style actions
    module(load="builtin:omfile" FileOwner="syslog" FileGroup="adm" dirOwner="syslog"
            dirGroup="adm" FileCreateMode="0640" DirCreateMode="0755")
    
    # Module to remove 1st space from message
    module(load="mmrm1stspace")
    
    # http://www.rsyslog.com/doc/v8-stable/configuration/input_directives/rsconf1_escapecontrolcharactersonreceive.html
    # Print recieved LF as-it-is, not like '\n'. For multi-line messages
    # Default: on
    $EscapeControlCharactersOnReceive off

    Теперь создадим RuleSet, разбирающий прилетевшие логи и раскладывающий их по папкам. Службы, полагающиеся для логирования исключительно на syslog, ожидают, что он сохранит время сообщения. Поэтому логи, прилетевшие со стандартными facility, мы будем сохранять в формате syslog, а для прилетевших с facility local0-local7 будем вынимать имя лога из поля TAG, и записывать только само сообщение без остальных полей syslog. Проблема с приклеенным к сообщению пробелом остаётся для RELP, потому что возникает ещё на этапе разбора сообщений, мы будем этот пробел отрезать.


    Для увеличения производительности будем писать асинхронно: asyncWriting="on" и с большим буфером ioBufferSize=64k. Не будем сбрасывать буфер после каждого полученного сообщения flushOnTXEnd="off", но будем это делать каждую секунду, чтобы логи появлялись на лог-сервере достаточно оперативно: flushInterval="1".


    ruleset(name="RemoteLogProcess") {
        # For facilities local0-7 set log filename from $programname field: replace __ with /
        # Message has arbitary format, syslog fields are not used
        if ( $syslogfacility >= 16 ) then
        {
            # Remove 1st space from message. Syslog protocol legacy
            action(type="mmrm1stspace")
    
            set $.logpath = replace($programname, "__", "/");
            action(type="omfile" dynaFileCacheSize="1024" dynaFile="RemoteLogSavePath" template="OnlyMsg"
            flushOnTXEnd="off" asyncWriting="on" flushInterval="1" ioBufferSize="64k")
    
        # Logs with filename defined from facility
        # Message has syslog format, syslog fields are used
        } else {
            if (($syslogfacility == 0)) then {
                set $.logpath = "kern";
            } else if (($syslogfacility == 4) or ($syslogfacility == 10)) then {
                set $.logpath = "auth";
            } else if (($syslogfacility == 9) or ($syslogfacility == 15)) then {
                set $.logpath = "cron";
            } else {
                set $.logpath ="syslog";
            }
            # Built-in template RSYSLOG_FileFormat: High-precision timestamps and timezone information
            action(type="omfile" dynaFileCacheSize="1024" dynaFile="RemoteLogSavePath" template="RSYSLOG_FileFormat"
            flushOnTXEnd="off" asyncWriting="on" flushInterval="1" ioBufferSize="64k")
        }
    } # ruleset

    Надёжная доставка сообщений. Очереди


    image


    изображение из блога k-max.name


    Для некоторых Actions выполнение может иногда тормозить или приостанавливаться, например пересылка логов по сети или запись в базу. Чтобы не терять сообщение и не мешать работать следующим Actions, можно использовать очереди. Каждому Action всегда сопоставлена очередь сообщений, по умолчанию это Direct Queue нулевого размера. Ещё есть основная очередь для поступивших из всех Input сообщений, её тоже можно настраивать.


    Виды очередей: дисковые, in-memory, и самый интересный вариант- комбинированный: Disk-Assisted Memory Queues. Такие очереди используют память и начинают использовать диск, если очередь в памяти переполняется, или надо сохранить неотправленные сообщения на время перезагрузки сервиса. Сообщения начнут записываться на диск, когда количество сообщений в очереди достигнет queue.highwatermark, и пререстанут сохраняться на диск, когда их количество упадёт до queue.lowwatermark. Чтобы неотправленные сообщения сохранялись на диск во время презагрузки сервиса, надо указать queue.saveonshutdown="on".


    Если персылка логов по сети или запись в базу была неуспешной, Action приостанавливается. rsyslog пытается возобновить работу Action через определённые, увеличивающиеся с каждой попыткой интервалы времени. Чтобы логи начали пересылаться вскоре после решения проблем, надо выставить action.resumeRetryCount="-1" (неограниченный) и интервал для остановки очереди поменьше: action.resumeInterval="10". Подробнее про параметры Actions.


    RuleSet на клиенте с очередью будет выглядеть так:


    ruleset(name="sendToLogserver") {
        # Queue: http://www.rsyslog.com/doc/v8-stable/concepts/queues.html#disk-assisted-memory-queues
        # Disk-Assisted Memory Queue: queue.type="LinkedList" + queue.filename
        # queue.size - max elements in memory
        # queue.highwatermark - when to start saving to disk
        # queue.lowwatermark - when to stop saving to disk
        # queue.saveonshutdown - save on disk between rsyslog shutdown
        # action.resumeRetryCount - number of retries for action, -1 = eternal
        # action.resumeInterval - interval to suspend action if destination can not be connected
        # After each 10 retries, the interval is extended: (numRetries / 10 + 1) * Action.ResumeInterval
        action(type="omrelp" Target="syslog.example.net" Port="20514" Template="LongTagForwardFormat"
        queue.type="LinkedList" queue.size="10000" queue.filename="q_sendToLogserver" queue.highwatermark="9000"
        queue.lowwatermark="50" queue.maxdiskspace="500m" queue.saveonshutdown="on" action.resumeRetryCount="-1"
        action.reportSuspension="on" action.reportSuspensionContinuation="on" action.resumeInterval="10")
    }

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


    ВНИМАНИЕ: При передачи сообщений из очереди после восстановления сети их относительный порядок может нарушаться(спасибо zystem за комментарий). Автор rsyslog ответил, что это ожидаемое поведение, подробнее можно почитать тут: http://www.gerhards.net/download/LinuxKongress2010rsyslog.pdf (section 7 "Concurrency-related Optimizations"). Вкратце: попытка сохранить строгий порядок сообщений при многопоточной обработке очереди приводила к падению производительности из-за необходимости блокировок потоков; понятие строгой последовательности сообщений может не иметь смысла для некоторых типов транспорта, многопоточных генераторов и приёмников сообщений.


    Отказоустойчивость


    Можно настроить Action для выполнения только в случае, если предыдущее Action было приостановлено: описание. Это позволяет настраивать failover конфигурации. Некоторые Actions используют транзакции для увеличения производительности. В таком случае, успех или неудача будут известны только после завершения транзакции, когда сообщения уже обработаны. Это может приводить к потере части сообщений без вызова failover Action. Чтобы такого не происходило, надо ставить параметр queue.dequeuebatchsize="1"(по-умолчанию 16), что может снизить производительность.


    ruleset(name="sendToLogserver") {
        action(type="omrelp" Target="syslog1.example.net" Port="20514" Template="LongTagForwardFormat")
        action(type="omrelp" Target="syslog2.example.net" Port="20514" Template="LongTagForwardFormat"
        action.execOnlyWhenPreviousIsSuspended="on" queue.dequeuebatchsize="1")
    }

    Эту возможность я пока не пробовал в продакшене.


    Взаимодействие с logrotate


    Логи, которые пишет сам rsyslog


    Нормально ротируются с использованием схемы по-умолчанию: smth.log переименовывается в smth.log.1, создаётся новый smth.log. В post-rotate action нужно послать SIGHUP процессу rsyslogd. Замечание: rsyslog не перезагружает конфигурацию при получении SIGHUP, только переоткрывает все лог-файлы.


    /var/log/someapp/*.log{
        weekly
        missingok
        rotate 5
        create 0644 syslog adm
        sharedscripts
        postrotate
            test -s run/rsyslogd.pid && kill -HUP $(cat /run/rsyslogd.pid)
            # postrotate script should always return 0
            true
        endscript
    }

    Логи, записываемые приложением и считываемые rsyslog


    Для приложений, способных переоткрывать файлы по запросу(SIGHUP или что-нибудь ещё), дополнительная конфигурация не требуется. rsyslog заметит изменения inode файла и переоткроет его.


    Проблемы появляются с опцией logrotate copytruncate, которая для smth.log создаёт его копию smth.log.1 и обрезает его до нулевого размера. rsyslog просто прекращяет читать новые строки из такого файла(по крайней мере, пока он не превысит размер до ротации). Начиная с версии 8.16.0, модуль imfile имеет опцию reopenOnTruncate (по-умолчанию "off", включается "on"). Эта опция заставляет rsyslog переоткрывать файл при обрезке(inode не изменилась, но размер уменьшился). Опция помечена как "экспериментальная", но у меня в продакшене работает нормально. Для версий старше 8.16.0, можно починить ротацию с copytruncate с помощью посылки сигнала SIGHUP процессу rsyslogd в post-rotate action.


    Замечание: на Debian/Ubuntu по умолчанию вывод и результат работы logrotate нигде не сохраняются, если он сломается — вы не узнаете. Я советую поправить это в /etc/cron.daily/logrotate.


    Итог


    Получилась достаточно гибкая и удобная конфигурация. Логи передаются как из файлов, так и из syslog. Многострочные сообщения передаются корректно. Перезагрузка лог-сервера не вызывает потерю данных. Для добавления новых логов достаточно обновить конфигурацию клиента, сервер трогать не надо.


    Работает для rsyslog v8, на более ранних версиях не проверялась. Для Ubuntu есть официальный ppa adiscon/v8-stable. Для CentOS/RHEL можно использовать официальный репозиторий.


    P.S. Перевод этой статьи на английский


    UPD: Добавлено замечание о нестрогом сохранении порядка сообщений при использовании очередей, спасибо zystem.


    UPD2: Добавлена секция о взаимодействии с logrotate.

    Поделиться публикацией
    Комментарии 12
      0
      у очередей rsyslog-а есть один неприятный момент. они гарантируют доставку после восстановления сети. но не гарантируют порядок доставки. на моих тестах rsyslog перемешивал строки лога. причем похоже это происходило на отправителе, а не на принимающем центральном лог сервере. для сравнения syslog-ng лог не перемешивает.
        0
        У нас такого пока вроде не замечал, надо будет проверить. Если есть чёткий алгоритм воспроизведения проблемы — можно написать разработчикам на гитхаб: https://github.com/rsyslog/rsyslog/issues
          +1

          Как воспроизвести


          источник


          module(load="imfile" mode="inotify")
          input(type="imfile"
                File="/var/log/1.log"
                Tag="FILE_test:")
          
          module(load="omrelp")
          :syslogtag, startswith, "FILE" action(type="omrelp" target="192.168.1.101" port="2514"
                action.resumeRetryCount="-1"
                queue.type="Disk"
                queue.filename="queue.logremote"
                queue.discardmark="1000000"
                queue.size="1000001"
                queue.maxfilesize="10m"
                queue.maxdiskspace="4g"
                queue.saveonshutdown="on")

          приемник


          module(load="imrelp")
          input(type="imrelp" port="2514")
          
          $template DYNtest,"/var/log/%HOSTNAME%/1.log"
          
          #crop leading space
          $template MSG,"%msg:2:999999999%\n"
          :syslogtag, isequal, FILE_test:            ?DYNtest;MSG

          Далее погасить rsyslog на приемнике для имитации проблем с сетью
          На источнике выполнить for i in {1..100000}; do echo $i >> /var/log/1.log; done


          Запустить rsyslog на приемнике и сравнить что прилетело в /var/log/%HOSTNAME%/1.log

            0

            Спасибо. Как будет время — проверю на последней версии и пойду пинать разработчиков на гитхабе.

              +1

              https://github.com/rsyslog/rsyslog/issues/1400


              посмотрим когда пофиксят

                0

                Тикет закрыли как "expected behaviour". Судя по http://www.rsyslog.com/doc/v8-stable/concepts/queues.html#performance, это действительно так для дефолтного queue.dequeuebatchsize=16, а queue.dequeuebatchsize=1 это вылечит, но негативно скажется на производительности. Как будет время — поэкспериментирую с этим и обновлю статью.

                  0

                  странно. syslog-ng это как-то делает без падения производительности

                    0

                    Статью обновил. Эксперименты показали, что queue.dequeuebatchsize=1 не помогает :(

        0

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


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


        • внезапное"затыкание" очереди и полная остановка клиентской системы в случае недоступности центрального сервера (лечится возвратом к UDP или созданием отдельной очереди на клиенте и тонкой её настройкой);
        • создание отдельного TCP-соединения на каждую строку вида @@ (для пересылки логов на сервер), что не является проблемой для клиента, но существенно для сервера при большом количестве подобных клиентов;
        • низкая производительность центрального сервера (при более чем 400-500 активных входящих соединений и небольшом количестве правил анализа сообщений), при переходе на syslog-ng нагрузка падает в 5-8 раз;
        • в отдельных версиях с пересылкой FQDN на центральный сервер при корректных настройках клиента передается только "короткое" имя сервера (известный баг).
        • непрозрачный и неудобный синтаксис (о чем, впрочем, уже было упомянуто в статье), нетривиальные правила разбора и изменения сообщений.

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

          0
          создание отдельного TCP-соединения на каждую строку вида @@ (для пересылки логов на сервер)

          Лечится выносом соединения в RuleSet и вызовом его для отправки call myruleset, как описано в статье. Получается только одно соединение.


          в отдельных версиях с пересылкой FQDN на центральный сервер при корректных настройках клиента передается только "короткое" имя сервера

          Это наверное какие-то старые версии, ну и в крайнем случае можно переопределить шаблон для отправки


          А в syslog-ng можно как-то использовать внешний обработчик для изменения логов перед сохранением/отправкой? Регэксп можно, но чтобы фильтровать номера карт без кучи ложных срабатываний, надо проверять корректность по алгоритму Луна, а этого регэкспом не сделаешь

            +1
            А в syslog-ng можно как-то использовать внешний обработчик для изменения логов перед сохранением/отправкой?

            Можно. Мы крутим на Perl, которому логи подаются через STDIN. Поток для преобразования (все сообщения категории LOCAL2) примерно 600-800 сообщений в секунду.


            filter f_local2 {
            facility(local2) 
            };
            
            destination d_parser { 
            program("/usr/local/bin/parser.pl" template("${R_UNIXTIME} ${HOST} ${MSG}\n")); 
            };
            
            log { 
            source(s_net); filter(f_local2); destination(d_parser); flags(final); 
            };

            Внешний скрипт может либо в файл писать, либо назад закидывать через syslog-библиотеку.

            0

            Добавлю: создавать отдельне TCP-соединие на каждую строку вида @@ в общем логично: это отдельные Action, у них могут быть свои настройки шаблона, очереди, других параметров действия. Если в syslog-ng сделать кучу destination, он тоже скорее всего создаст для каждого из них отдельное соединение.


            Но да, в syslog-ng оптимальную конфигурацию написать проще, а в rsyslog проще пользоваться legacy-синтаксисом и написать неоптимальную :(

          Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

          Самое читаемое