SysLogHandler messages grouped on one line on remote server

Question

I am trying to use python logging module to log messages to a remote rsyslog server. The messages are received, but its concatenating the messages together on one line for each message. Here is an example of my code:

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")

On the server side, I'm added the following the following line to the /etc/rsyslog.d/50-default.conf to disable /var/log/syslog logging for USER, LOCAL0 and LOCAL1 facilities (which I use for app, perf, and audit logging).

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

And I update the to the /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

So after doing all that when I run the python code (listed above) these are these are the messages I'm seeing on the remote server:

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

As you can see the messages are being filtered to the proper log file, but they're being concatenated onto one line. I'm guessing that its doing it because they arrive at the same time, but I'd like the messages to be split onto separate lines.

In addition, I've tried adding a formatter to the SysLogHandler so that it inserts a line break to the message like this:

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

However, this really screws it up:

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

As you can see the first message gets put into the right file for the audit and performance logs, but then all the other messages get put into the application log file. However, there is definitely a line break now.

My question is, I want to filter the messages based on facility, but with each message on a seperate line. How can I do this using the python logging library? I guess I could take a look at the syslog library?

score 3 · Accepted Answer · answered Oct 23 '18 at 21:07

So I came across this python bug: https://bugs.python.org/issue28404

So I took a look at the source code (nice thing about python), specifically the SysLogHander.emit() method:

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)

As you can see it adds a '\000' to the end of the message by default, so if I set this to False and then set a Formatter that adds a line break, then things work the way I expect. Like this:

        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

Thanks for your help @Sraw, I tried to use UDP, but never got the message. After applying these changes this is what I see in my log files:

$ 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

score 1 · Answer 2 · answered Oct 23 '18 at 14:23

1

I believe tcp stream makes it more complicated. When you are using tcp stream, rsyslog won't help you to split the message, it is all on your own.

Why not use udp protocol? In this case, every single message will be treated as a single log. So you don't need to add \n manually. And manually adding \n will makes you impossible to log multiple line logs correctly.

So my suggestion is changing to udp protocol and:

# Disable escaping to accept multiple line log
$EscapeControlCharactersOnReceive off

answered Oct 23 '18 at 14:23

Sraw

18,892
11
54
87

Could you give some more details? I added `sys_log_handler = handlers.SysLogHandler(rsyslog_address, syslog_facility, socktype=socket.SOCK_DGRAM)` and re-ran the code, but I'm not seeing messages on the server now. How do I configure the rsyslog server to accept udp connections? I added the `$EscapeControlCharactersOnReceive off` to the /etc/rsyslog.config file. – Craig Oct 23 '18 at 14:54
@Craig That is just above your tcp configuration `# provides TCP syslog reception`. Uncomment those lines below `# provides UDP syslog reception`. – Sraw Oct 23 '18 at 15:00
Hm... I commented the tcp lines and uncommented the udp lines and restarted rsyslog, but I'm not seeing any messages on the server now. – Craig Oct 23 '18 at 15:42
UDP isn't reliable, so you might lose log messages or have them delivered out of order. But this would depend on network and networking performance, so you could test the logging many times successfully but find that it fails under different load conditions. – Arthur Sep 05 '19 at 19:01

tabata · Answer 3 · 2022-10-04T15:01:31.400

I came accross the same issue.

capture multiline events with rsyslog and storing them to file

The cause is related to the question above.
NULL character is not handled as delimilter in imtcp.

My solution was setting AddtlFrameDelimiter="0", something like below.

module(load="imtcp" AddtlFrameDelimiter="0")
input(type="imtcp" port="514")

reference:

EDITED 2022/10/04

The previous example was using input parameter. And AddtlFrameDelimiter's input paramter has been newly supported since v8.2106.0. Therefore, I changed the input paramter's example into old style module golbal parameter's one.

# module golbal parameter case, supported since v6.XXXX
module(load="imtcp" AddtlFrameDelimiter="0")
input(type="imtcp" port="514")

# input paramter case, supported since v8.2106.0
module(load="imtcp")
input(type="imtcp" port="514" AddtlFrameDelimiter="0")

SysLogHandler messages grouped on one line on remote server

3 Answers3

Linked