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 以禁用 USER、LOCAL0 和 LOCAL1 设施的 /var/log/syslog 日志记录（我用于应用、性能和审计日志记录）。

*.*;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 日志库来做到这一点？我想我可以看看 syslog 库？

Answer 1

我相信 tcp 流会使它变得更复杂。当你使用 tcp 流时，rsyslog 不会帮你拆分消息，它是你自己的。

为什么不使用 udp 协议？在这种情况下，每条消息都将被视为单个日志。所以你不需要手动添加\n。并且手动添加\n 会使您无法正确记录多行日志。

所以我的建议是更改为 udp 协议并且：

# Disable escaping to accept multiple line log
$EscapeControlCharactersOnReceive off

Answer 2

所以我遇到了这个 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