Сообщения SysLogHandler, сгруппированные в одну строку на удаленном сервере

Question

Я пытаюсь использовать модуль регистрации Python для записи сообщений на удаленный сервер rsyslog.Сообщения принимаются, но все сообщения объединяются в одну строку для каждого сообщения.Вот пример моего кода:

to_syslog_priority: dict = {
    Level.EMERGENCY: 'emerg',
    Level.ALERT: 'alert',
    Level.CRITICAL: 'crit',
    Level.ERROR: 'err',
    Level.NOTICE: 'notice',
    Level.WARNING: 'warning',
    Level.INFO: 'info',
    Level.DEBUG: 'debug',
    Level.PERF: 'info',
    Level.AUDIT: 'info'
}

@staticmethod
def make_logger(*, name: str, log_level: Level, rsyslog_address: Tuple[str, int], syslog_facility: int) -> Logger:
    """Initialize the logger with the given attributes"""
    logger = logging.getLogger(name)
    num_handlers = len(logger.handlers)
    for i in range(0, num_handlers):
        logger.removeHandler(logger.handlers[0])
    logger.setLevel(log_level.value)
    syslog_priority = Log.to_syslog_priority[log_level]
    with Timeout(seconds=RSYSLOG_TIMEOUT, timeout_message="Cannot reach {}".format(rsyslog_address)):
        sys_log_handler = handlers.SysLogHandler(rsyslog_address, syslog_facility, socket.SOCK_STREAM)
        # There is a bug in the python implementation that prevents custom log levels
        # See /usr/lib/python3.6/logging/handlers.SysLogHandler.priority_map on line 789. It can only map
        # to 5 log levels instead of the 8 we've implemented.
        sys_log_handler.mapPriority = lambda *args: syslog_priority
        logger.addHandler(sys_log_handler)
        stdout_handler = logging.StreamHandler(sys.stdout)
        logger.addHandler(stdout_handler)
    return logger

if __name__ == '__main__':
    app_logger = Log.make_logger(name='APP', log_level=Log.Level.INFO, rsyslog_address=('localhost', 514),
                                 syslog_facility=SysLogHandler.LOG_USER)
    audit_logger = Log.make_logger(name='PERF', log_level=Log.Level.INFO, rsyslog_address=('localhost', 514),
                                   syslog_facility=SysLogHandler.LOG_LOCAL0)
    perf_logger = Log.make_logger(name='AUDIT', log_level=Log.Level.INFO, rsyslog_address=('localhost', 514),
                                  syslog_facility=SysLogHandler.LOG_LOCAL1)

    log = Log(log_level=Log.Level.WARNING, component='testing', worker='tester', version='1.0', rsyslog_srv='localhost',
              rsyslog_port=30514)
    app_logger.warning("Testing warning logging")
    perf_logger.info("Testing performance logging1")
    audit_logger.info("Testing aduit logging1")
    audit_logger.info("Testing audit logging2")
    app_logger.critical("Testing critical logging")
    perf_logger.info("Testing performance logging2")
    audit_logger.info("Testing audit logging3")
    app_logger.error("Testing error logging")

На стороне сервера я добавил следующую строку в /etc/rsyslog.d/50-default.conf, чтобы отключить / var /ведение журнала log / syslog для средств USER, LOCAL0 и LOCAL1 (которые я использую для ведения журналов приложений, perf и аудита).

*.*;user,local0,local1,auth,authpriv.none       -/var/log/syslog

И я обновляю до /etc/rsyslog.config:

#  /etc/rsyslog.conf    Configuration file for rsyslog.
#
#           For more information see
#           /usr/share/doc/rsyslog-doc/html/rsyslog_conf.html
#
#  Default logging rules can be found in /etc/rsyslog.d/50-default.conf


#################
#### MODULES ####
#################

module(load="imuxsock") # provides support for local system logging
#module(load="immark")  # provides --MARK-- message capability

# provides UDP syslog reception
#module(load="imudp")
#input(type="imudp" port="514")

# provides TCP syslog reception
module(load="imtcp")
input(type="imtcp" port="514")

# provides kernel logging support and enable non-kernel klog messages
module(load="imklog" permitnonkernelfacility="on")

###########################
#### GLOBAL DIRECTIVES ####
###########################

#
# Use traditional timestamp format.
# To enable high precision timestamps, comment out the following line.
#
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

# Filter duplicated messages
$RepeatedMsgReduction on

#
# Set the default permissions for all log files.
#
$FileOwner syslog
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022
$PrivDropToUser syslog
$PrivDropToGroup syslog

#
# Where to place spool and state files
#
$WorkDirectory /var/spool/rsyslog

#
# Include all config files in /etc/rsyslog.d/
#
$IncludeConfig /etc/rsyslog.d/*.conf
user.*   -/log/app.log
local0.*   -/log/audit.log
local1.*   -/log/perf.log

Итак, после выполнения всего этого, когда я запускаю код Python (указанный выше), это сообщения, которые я вижу на удаленном сервере:

for log in /log/*.log; do echo "${log} >>>"; cat ${log}; echo "<<< ${log}"; echo; done
    /log/app.log >>>
    Oct 23 13:00:23 de4bba6ac1dd rsyslogd: imklog: cannot open kernel log (/proc/kmsg): Operation not permitted.
    Oct 23 13:01:34 Testing warning logging#000<14>Testing critical logging#000<14>Testing error logging
    <<< /log/app.log

    /log/audit.log >>>
    Oct 23 13:01:34 Testing aduit logging1#000<134>Testing audit logging2#000<134>Testing audit logging3
    <<< /log/audit.log

    /log/perf.log >>>
    Oct 23 13:01:34 Testing performance logging1#000<142>Testing performance logging2
    <<< /log/perf.log

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

Кроме того, я попытался добавить средство форматирования в SysLogHandler, чтобычто он вставляет в сообщение разрыв строки следующим образом:

sys_log_handler.setFormatter(logging.Formatter('%(message)s\n'))

Однако, это действительно облажает его:

for log in /log/*.log; do echo "${log} >>>"; cat ${log}; echo "<<< ${log}"; echo; done
    /log/app.log >>>
    Oct 23 13:00:23 de4bba6ac1dd rsyslogd: imklog: cannot open kernel log (/proc/kmsg): Operation not permitted.
    Oct 23 13:01:34 Testing warning logging#000<14>Testing critical logging#000<14>Testing error logging
    Oct 23 13:12:00 Testing warning logging
    Oct 23 13:12:00 172.17.0.1 #000<134>Testing audit logging2
    Oct 23 13:12:00 172.17.0.1 #000<14>Testing critical logging
    Oct 23 13:12:00 172.17.0.1 #000<142>Testing performance logging2
    Oct 23 13:12:00 172.17.0.1 #000<134>Testing audit logging3
    Oct 23 13:12:00 172.17.0.1 #000<14>Testing error logging
    Oct 23 13:12:00 172.17.0.1  
    <<< /log/app.log

    /log/audit.log >>>
    Oct 23 13:01:34 Testing aduit logging1#000<134>Testing audit logging2#000<134>Testing audit logging3
    Oct 23 13:12:00 Testing aduit logging1
    <<< /log/audit.log

    /log/perf.log >>>
    Oct 23 13:01:34 Testing performance logging1#000<142>Testing performance logging2
    Oct 23 13:12:00 Testing performance logging1
    <<< /log/perf.log

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

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

Answer 1

Итак, я столкнулся с этой ошибкой Python: https://bugs.python.org/issue28404

Итак, я взглянул на исходный код (хорошая вещь о Python), в частности метод SysLogHander.emit ():

def emit(self, record):
    """
    Emit a record.

    The record is formatted, and then sent to the syslog server. If
    exception information is present, it is NOT sent to the server.
    """
    try:
        msg = self.format(record)
        if self.ident:
            msg = self.ident + msg
        if self.append_nul:
# Next line is always added by default
            msg += '\000' 

        # We need to convert record level to lowercase, maybe this will
        # change in the future.
        prio = '<%d>' % self.encodePriority(self.facility,
                                            self.mapPriority(record.levelname))
        prio = prio.encode('utf-8')
        # Message is a string. Convert to bytes as required by RFC 5424
        msg = msg.encode('utf-8')
        msg = prio + msg
        if self.unixsocket:
            try:
                self.socket.send(msg)
            except OSError:
                self.socket.close()
                self._connect_unixsocket(self.address)
                self.socket.send(msg)
        elif self.socktype == socket.SOCK_DGRAM:
            self.socket.sendto(msg, self.address)
        else:
            self.socket.sendall(msg)
    except Exception:
        self.handleError(record)

Как вы можете видеть, он добавляет «\ 000» к концу сообщения по умолчанию, поэтому, если я установлю это значение в False, а затем установлю Formatter, который добавляет разрыв строки, тогда все будет работать так, как я ожидаю.Например:

        sys_log_handler.mapPriority = lambda *args: syslog_priority
        # This will add a line break to the message before it is 'emitted' which ensures that the messages are
        # split up over multiple lines, see https://bugs.python.org/issue28404
        sys_log_handler.setFormatter(logging.Formatter('%(message)s\n'))
        # In order for the above to work, then we need to ensure that the null terminator is not included
        sys_log_handler.append_nul = False

Спасибо за вашу помощь @Sraw, я пытался использовать UDP, но не получил сообщение.После применения этих изменений это то, что я вижу в моих файлах журнала:

$ for log in /tmp/logging_test/*.log; do echo "${log} >>>"; cat ${log}; echo "<<< ${log}"; echo; done
/tmp/logging_test/app.log >>>
Oct 23 21:06:40 083c9501574d rsyslogd: imklog: cannot open kernel log (/proc/kmsg): Operation not permitted.
Oct 23 21:06:45 Testing warning logging
Oct 23 21:06:45 Testing critical logging
Oct 23 21:06:45 Testing error logging
<<< /tmp/logging_test/app.log

/tmp/logging_test/audit.log >>>
Oct 23 21:06:45 Testing audit logging1
Oct 23 21:06:45 Testing audit logging2
Oct 23 21:06:45 Testing audit logging3
<<< /tmp/logging_test/audit.log

/tmp/logging_test/perf.log >>>
Oct 23 21:06:45 Testing performance logging1
Oct 23 21:06:45 Testing performance logging2
<<< /tmp/logging_test/perf.log

Answer 2

Я считаю, что tcp stream усложняет процесс.Когда вы используете tcp stream, rsyslog не поможет вам разбить сообщение, это все самостоятельно.

Почему бы не использовать протокол udp?В этом случае каждое отдельное сообщение будет обрабатываться как один журнал.Так что вам не нужно добавлять \n вручную.А добавление \n вручную сделает невозможным правильное ведение многострочных журналов.

Поэтому мое предложение меняется на протокол udp и:

# Disable escaping to accept multiple line log
$EscapeControlCharactersOnReceive off