rsyslog template "eating" the first part of a message

Question

I'm logging messages to syslog with Python's SysLogHandler. The problem is that startswith combined with a template seems to "eat" the beginning of the logged string.

Rsyslogd is version 8.4.2, Python 2.7.9 (same behaviour on 2.7.11). It does not seem to happen on rsyslogd 7.x with Python 2.7.4 however.

Example:

#!/usr/bin/env python
import logging
from logging.handlers import SysLogHandler

my_fmt = logging.Formatter('%(name)s:%(message)s', '%Y-%m-%d %H:%M:%S')
foo_handler = SysLogHandler(address='/dev/log', facility=SysLogHandler.LOG_LOCAL5)
foo_handler.setLevel(logging.INFO)
foo_handler.setFormatter(my_fmt)

foo = logging.getLogger('foo')
foo.setLevel(logging.INFO)
foo.addHandler(foo_handler)
foo.propagate = False

foo.info("This is foo")

With this rsyslog configuration:

$template myt,"%TIMESTAMP:::date-rfc3339%%msg:::sp-if-no-1st-sp%%msg:::drop-last-lf%\n"

if $syslogfacility-text == "local5" then {
    if $msg startswith "foo" then {
        action(type="omfile" file="/var/log/foo.log" template="myt")
    } else {
        action(type="omfile" file="/var/log/bar.log" template="myt")
    }
    stop
}

Produces the following:

=> /var/log/bar.log <==
2016-06-29T17:29:55.330941+01:00 is foo

Notice the missing 'This' in the message.

Conversely, removing the use the template in rsyslog config file results in:

==> /var/log/bar.log <==
Jun 29 18:19:40 localhost foo:This is foo

Removing %msg:::sp-if-no-1st-sp% from the template does not seem to help either.

score 0 · Answer 1 · answered Jul 01 '16 at 13:23

The solution appears to be:

Use $syslogtag startswith instead of $msg startswith
In the python source, separate the name from the rest of the string with an empty space: logging.Formatter('%(name)s: %(message)s', '%Y-%m-%d %H:%M:%S')

I am unsure why this wasn't a problem on 2.7.4 and if anyone finds the reason please post a comment below.

rsyslog template "eating" the first part of a message

1 Answers1