Home / user-1136135

CornBouyed's questions

Martin Hope
CornBouyed
Asked: 2024-09-16 18:03:01 +0800 CST
  • 5

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