Journal log messages duplicated

I’ve installed Mender on my target using Buildroot. When checking the logs for the client I noticed that error and warning log messages are duplicated, but info are not. Once with normal formatting and then again with either bold yellow or red formatting. Perhaps this is just a systemd journal configuration issue on my end, but I was curious if anyone has experienced this same issue.

Hi @pamolloy,

Thanks for reporting this! As we understand it, this is caused by the client both generating output which is captured by journald, as well as directly writing to syslog. So if journald also writes to the syslog, then you see the duplication. We’re looking into it now.

Greetz,
Josef

1 Like

Hi @pamolloy,

To confirm our analysis, can you please provide the output of

file /dev/log /var/run/syslog /var/run/log

and the .service file in use for the system logger, presumably syslogd, syslog-ng or rsyslog, and while you’re at it, also systemd-journald? (EDIT: not mender-client)

Thanks!

# file /dev/log /var/run/syslog /var/run/log
/dev/log:        symbolic link to /run/systemd/journal/dev-log
/var/run/syslog: cannot open `/var/run/syslog' (No such file or directory)
/var/run/log:    directory

I’m only using systemd-journald and the main service file comes from systemd. I’ve added a diff from the latest upstream template for the service file.

diff systemd-journald.service.in /usr/lib/systemd/system/systemd-journald.service 
--- systemd-journald.service.in
+++ /usr/lib/systemd/system/systemd-journald.service
@@ -15,14 +15,9 @@
 After=systemd-journald.socket systemd-journald-dev-log.socket systemd-journald-audit.socket syslog.socket
 Before=sysinit.target
 
-# Mount and swap units need the journal socket units. If they were removed by
-# an isolate request the mount and swap units would be removed too, hence let's
-# exclude systemd-journald and its sockets from isolate requests.
-IgnoreOnIsolate=yes
-
 [Service]
 DeviceAllow=char-* rw
-ExecStart={{ROOTLIBEXECDIR}}/systemd-journald
+ExecStart=/usr/lib/systemd/systemd-journald
 FileDescriptorStoreMax=4224
 IPAddressDeny=any
 LockPersonality=yes
@@ -44,7 +39,7 @@
 SystemCallErrorNumber=EPERM
 SystemCallFilter=@system-service
 Type=notify
-{{SERVICE_WATCHDOG}}
+WatchdogSec=3min
 
 # In case you're wondering why CAP_SYS_PTRACE is needed, access to
 # /proc/<pid>/exe requires this capability. Thus if this capability is missing
@@ -53,5 +48,4 @@
 
 # If there are many split up journal files we need a lot of fds to access them
 # all in parallel.
-LimitNOFILE={{HIGH_RLIMIT_NOFILE}}
-
+LimitNOFILE=524288

Note that when I run mender daemon manually I get the following message three times:

WARN[0063] Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before. 
WARN[0064] Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before. 
WARN[0068] Returning artifact name from /etc/mender/artifact_info file. This is a fallback, in case the information can not be retrieved from the database, and is only expected when an update has never been installed before. 

Is there a way to prevent the warning about artifact_info from getting printed? Or maybe the default config is causing that polling that too often? I feel like I’m missing some persistent storage for Mender because even after several updates I still see this warning.

Hello @pamolloy ,

Thanks for bringing this up.

Regarding the duplicate log messages in the journal, in your configuration journald symlinks /dev/log to /run/systemd/journal/dev-log, which is a socket that journald listens to. Additionally, mender-client is configured by default to forward log entries to the standard syslogger ( syslogd, syslog-ng or rsyslog). Most sysloggers listen to /dev/log. Presumably, this is why duplicate log messages happen as two identical streams are fed into journald; one from /run/systemd/journal/dev-log and one from stdout.

To fix the problem, try the following:

  • In /lib/systemd/system/mender-client.service, change

ExecStart=/usr/bin/mender daemon
to
ExecStart=/usr/bin/mender --no-syslog daemon.

  • (optionally) if you want log messages to be forwarded to /var/log/syslog, make sure the standard syslogger listens to /run/systemd/journal/syslog and set ForwardToSyslog=yes in your /etc/systemd/journald.conf.

Hope this helps :slight_smile:

1 Like

@pamolloy

With regards to the artifact_info point that you brought up, I just need to clarify some things. So to understand this correctly, did you run the mender-client in the shell alongside a mender-client already running and managed by systemd, while doing updates?

The one spawned in the shell, does it run with root privileges?

What version of mender are you running?

Thanks for the detailed reply! --no-syslog is exactly what I needed.

2 Likes

I believe this was the result of not persisting Mender data between updates. I now pass a directory that is persisted to Mender with --data.

2 Likes