1

I am working on a program that sends logs with syslog(). Then I configured rsyslog service to save logs in a file under Linux. Most of the time this process works normally. But sometimes, some of the logs are not sent to rsyslog. Instead, I can watch them when I use the journalctl -f -u Myservice command. I am using the Debian Jessie version of Linux. Do you have any idea what is the problem and how to solve it?

Rachid K.
  • 4,490
  • 3
  • 11
  • 30
hpirlo
  • 133
  • 1
  • 12

3 Answers3

4

Loosely speaking, with systemd, the logs are managed as follow:

Process calls syslog() --writes in--> /dev/log = /run/systemd/journal/dev-log --read by--> systemd-journald --forwards to--> /run/systemd/journal/syslog --read by--> rsyslogd

Let's look at it in more details...

/lib/systemd/system/systemd-journald-dev-log.socket is the systemd socket unit to capture the messages from /dev/log:

[...]
[Socket]
Service=systemd-journald.service
ListenDatagram=/run/systemd/journal/dev-log
Symlinks=/dev/log
SocketMode=0666
[...]

In the above socket unit, there are two important things:

  • The service which is triggered for this socket is systemd-journald;
  • /dev/log is a symbolic link onto /run/systemd/journal/dev-log:
$ ls -l /dev/log
lrwxrwxrwx 1 root root 28 sept.  14 09:47 /dev/log -> /run/systemd/journal/dev-log
$ ls -l /run/systemd/journal/dev-log
srw-rw-rw- 1 root root 0 sept.  14 09:47 /run/systemd/journal/dev-log

Hence any process calling syslog() actually writes into /dev/log synonymous of /run/systemd/journal/dev-log. As systemd-journald reads from this socket, this makes it capture the logs of all the processes writing into /dev/log. But systemd implements a mechanism to forward those logs to any "registered" service.

There is a syslog.socket unit which sets up the /run/systemd/journal/syslog socket:

[...]
[Socket]
ListenDatagram=/run/systemd/journal/syslog
[...]

The corresponding syslog.service is triggered afterwards. The latter is actually a symbolic link onto the actual syslog service (e.g. rsyslogd or syslog-ng). Here is an example, where it is a symbolic link onto rsyslog.service:

$ ls -l /etc/systemd/system/syslog.service 
lrwxrwxrwx 1 root root 35 juin    5  2021 /etc/systemd/system/syslog.service -> /lib/systemd/system/rsyslog.service

The content of the latter service, executes rsyslogd daemon:

[...]
[Service]
Type=notify
ExecStart=/usr/sbin/rsyslogd -n -iNONE
[...]

We can verify its activation looking at the status of the syslog service (field "TriggeredBy"):

$ systemctl status syslog | cat
* rsyslog.service - System Logging Service
     Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2022-09-14 09:47:22 CEST; 32min ago
TriggeredBy: * syslog.socket
       Docs: man:rsyslogd(8)
             https://www.rsyslog.com/doc/
   Main PID: 728 (rsyslogd)
      Tasks: 4 (limit: 18404)
     Memory: 3.9M
     CGroup: /system.slice/rsyslog.service
             `-728 /usr/sbin/rsyslogd -n -iNONE
sept. 14 09:47:22 xxx systemd[1]: Starting System Logging Service...
sept. 14 09:47:22 xxx rsyslogd[728]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2001.0]

The startup messages above shows that rsyslogd is passed the unix socket /run/systemd/journal/syslog (file descriptor id 3). This is managed by the imuxsock module of rsyslogd. This is indeed part of the file descriptors opened by rsyslogd process:

$ sudo ls -l /proc/`pidof rsyslogd`/fd
total 0
lr-x------ 1 root root 64 sept.  14 09:47 0 -> /dev/null
l-wx------ 1 root root 64 sept.  14 09:47 1 -> /dev/null
l-wx------ 1 root root 64 sept.  14 09:47 10 -> /var/log/kern.log
l-wx------ 1 root root 64 sept.  14 09:47 11 -> /var/log/mail.log
l-wx------ 1 root root 64 sept.  14 09:47 2 -> /dev/null
lrwx------ 1 root root 64 sept.  14 09:47 3 -> 'socket:[1339]'
lr-x------ 1 root root 64 sept.  14 09:47 4 -> /dev/urandom
lrwx------ 1 root root 64 sept.  14 09:47 5 -> 'socket:[36221]'
lr-x------ 1 root root 64 sept.  14 09:47 6 -> /proc/kmsg
lrwx------ 1 root root 64 sept.  14 09:47 7 -> 'socket:[36999]'
l-wx------ 1 root root 64 sept.  14 09:47 8 -> /var/log/syslog
l-wx------ 1 root root 64 sept.  14 09:47 9 -> /var/log/auth.log

The configuration of systemd-journald decides if what is read from /run/systemd/journal/dev-log is forwarded or not to /run/systemd/journal/syslog:

$ cat /etc/systemd/journald.conf | grep ForwardToSyslog
#ForwardToSyslog=yes

The above commented line means that the default is "yes".

To answer the OP's question

If some of the logs sent by the processes are not seen in rsyslogd's output but seen in the systemd-journald's output, this may mean that rsyslogd is not started early enough compared to the application. So, the latter's logging are read by systemd-journald but are not forwarded to rsyslogd. The latter starts in the systemd's multi-user.target whereas systemd-journald is launched at the very beginning of the system startup.
To verify that, the result of systemctl status syslog.service displays the activation date. Compare it to the activation date of systemd-journald.service and the one of the application.
A synchronization key like "After=syslog.service" may be missing in the service file of the application.

Further references

https://www.freedesktop.org/wiki/Software/systemd/syslog/

Rachid K.
  • 4,490
  • 3
  • 11
  • 30
0

This totally depends on whether or not the rsyslog service is running. Please check if rsyslog is running when you face the issue.

Rachid K.
  • 4,490
  • 3
  • 11
  • 30
Niraj Nandane
  • 1,318
  • 1
  • 13
  • 24
0

Finally, I found a good answer. In the rsyslog config file in we can add different methods to get the messages. I had many filters with the contains filter. this significantly reduced the performance since it needs to completely search the string for the filter value. Then I found that the startswith filter is far better in searching for a value in a string. I changed the message structure so that I can use the startswith filter. then I changed the rsyslog filter to startswith. now the performance is much better and no message sent to the journal. the syntax is like this:

:msg, startswith, "val" # instead of (:msg, contains, "val")

hpirlo
  • 133
  • 1
  • 12