Home / server / Questions / 1165289
Accepted
CornBouyed
Asked: 2024-09-16 18:03:01 +0800 CST

Why is rsyslog logging duplicate messages from systemd journal?

  • 772

Why might rsyslog be logging duplicate messages from the systemd journal?

I am aware of the known issues surrounding systemd journal corruption (see i.e. the warning under the "Purpose" section here: https://www.rsyslog.com/doc/configuration/modules/imjournal.html) but I don't think that is the issue I am encountering. I am running Ubuntu 24.04, rsyslog 8.2312.0-3ubuntu9, and systemd 255.4-1ubuntu8.4.

I have multiple hosts running an application named "foobar" as a systemd service and logging to the systemd journal. I also run rsyslog as a systemd service and it is configured to forward the foobar logs in JSON format from the systemd journal to a central logging server. The rsyslog configuration on each host looks like:

module(load="imjournal" StateFile="journalState" IgnorePreviousMessages="on")
module(load="mmjsonparse")
    
template(name="foobarJSON" type="string" string="%TIMESTAMP% %HOSTNAME% %syslogtag% @cee: %$!all-json%\n" )

if $syslogfacility-text == "user" and $programname == "foobar" then {
    user.* action(type="omfwd" target="central-logs.server" port="514" protocol="tcp" template="foobarJSON")
}

I am also running rsyslog as a systemd service on the central logging server and writing the foobar logs from each server to local files inside a separate subdirectory for each host. The rsyslog configuration on this host looks like:

module(load="imtcp")
input(type="imtcp" address="123.456.789.0" port="514")

template(name="foobarHostLogs" type="string" string="/var/logs/%PROGRAMNAME%/%HOSTNAME%/%$year%/%$month%/%$day%.log")

module(load="builtin:omfile" DirCreateMode="0755")

if $fromhost-ip != '127.0.0.1' then {
    action(type="omfile" dynaFile="foobarHostLogs")

    & stop
}

Running journalctl -u foobar on any of the foobar hosts I do not see any duplicate messages. However, when looking in the log files on the central logging server I see every message is duplicated: there is at least one message containing only the "msg" field from the systemd journal (although sometimes I see two identical lines containing only "msg"), followed immediately by a line with the exact same timestamp and "msg" value plus all of the other metadata fields from the systemd journal.

For example (I removed several extra fields from the second line below, but hopefully you get the idea):

2024-09-15T00:00:00+00:00 host-a foobar[123456]: @cee: { "msg": "Hello, world!" }
2024-09-15T00:00:00+00:00 host-a foobar[123456]: @cee: { "_TRANSPORT": "journal", "_PID": "123456", "_UID": "1000", "_GID": "1000", "_COMM": "foobar", "_EXE": "\/usr\/local\/bin\/foobar", "_CMDLINE": ".\/foobar", "_CAP_EFFECTIVE": "0", "_SELINUX_CONTEXT": "unconfined\n", "MESSAGE": "Hello, world!", "msg": "Hello, world!" }
rsyslog

2 Answers

  1. It sounds like you might have both syslog forwarding methods configured on the client hosts – in addition to reading logs via imjournal (which provides all metadata), it likely also receives the same logs via imuxsock in /run/systemd (the legacy forwarding method without metadata). Make sure ForwardToSyslog= is disabled in your journald.conf.

    • 0
  2. Best Answer

    Ok, I was able to figure it out. @u1686_grawity was correct that the root cause was rsyslog reading messages from systemd journal using both the imuxsock and imjournal input modules, but simply disabling ForwardtoSyslog for journald was not enough to stop the duplicates.

    Instead, I had to configure rsyslog to only forward the message received from imjournal to the central logging server by adding the condition $inputname == "imjournal" to the original if-clause, i.e.:

    module(load="imjournal" StateFile="journalState" IgnorePreviousMessages="on")
module(load="mmjsonparse")
    
template(name="foobarJSON" type="string" string="%TIMESTAMP% %HOSTNAME% %syslogtag% @cee: %$!all-json%\n" )

if $inputname == "imjournal" and $syslogfacility-text == "user" and $programname == "foobar" then {
    action(type="mmjsonparse")
    user.* action(type="omfwd" target="central-logs.server" port="514" protocol="tcp" template="foobarJSON")
}

    Also, I figured out why I was getting those empty messages: I forgot to actually invoke the mmjsonparse action to parse the structured log message and get all of the individual fields from the journald message, so I added that line to my working config example above as well.

    • 0