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

Задача

Передавать лог-файлы на центральный сервер. При недоступности сервера не терять сообщения, а накапливать и передавать при его появлении в сети. Корректно передавать многострочные сообщения.

Дополнительно:

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

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

Выбор софта

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

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

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

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

Сообщения 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. Нестандарт, только некоторые реализации.

Альтернатива: 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..."). Вот некоторые из них:
  
  • omfile — вывод в файл
  • omfwd — пересылка по сети, через udp или tcp
  • omrelp — пересылка по сети по протоколу RELP
  • onmysql, ompgsql, omoracle — запись в базу
  • omelasticsearch — запись в ElasticSearch
  • omamqp1 — пересылка по протоколу AMQP 1.0
  • весь список модулей вывода

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

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

Записываем все сообщения категорий 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(это режим по-умолчанию).

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

Для работы с лог-файлами, содержащими многострочные сообщения, модуль 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

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

изображение из блога 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")
}

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

Итог

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

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

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

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