Invalid SYSLOG_PID for (systemd) journal messages

[sigv]

On Ubuntu 20.04 (Focal), official package versioned 2.2.3-3.

We are seeing SYSLOG_PID field consist of backend information (such as 'EXAMPLE.COM]') or 'sudo', 'nss' or 'pam'.
According to systemd.journal-fields, this field is not explicitly validated, and should be provided as a number from the application.

This incorrect (non-numeric) PID causes trouble for our Journalbeat to Elasticsearch centralized logging implementation, due to it trying to parse it as a long.

# journalctl -o verbose -u sssd.service
Mon 2020-12-07 08:40:47.081946 UTC []
    SYSLOG_FACILITY=3
    PRIORITY=6
    _UID=0
    _GID=0
    _SYSTEMD_SLICE=system.slice
    _BOOT_ID=e75ace3ffdb548179ccb8a011e91d4b1
    _MACHINE_ID=9a1d010d2e7743a5a120a5b96e9113ec
    _HOSTNAME=servername.example.com
    _TRANSPORT=syslog
    _CAP_EFFECTIVE=3fffffffff
    _COMM=sssd_be
    SYSLOG_IDENTIFIER=sssd[be
    SYSLOG_PID=EXAMPLE.COM]
    _EXE=/usr/libexec/sssd/sssd_be
    _CMDLINE=/usr/libexec/sssd/sssd_be --domain EXAMPLE.COM --uid 0 --gid 0 --logger=files
    _SELINUX_CONTEXT=/usr/sbin/sssd//null-/usr/libexec/sssd/sssd_be (complain)
    _SYSTEMD_CGROUP=/system.slice/sssd.service
    _SYSTEMD_UNIT=sssd.service
    MESSAGE=Starting up
    _SYSTEMD_INVOCATION_ID=df989931f2fa48dcb97b98a9dfe378c3
    _PID=838277
    SYSLOG_TIMESTAMP=Dec  7 08:00:00
    _SOURCE_REALTIME_TIMESTAMP=1607328000000000

# grep sssd /var/log/syslog
Dec  7 08:00:00 servername sssd[be[EXAMPLE.COM]]: Starting up
Dec  7 08:00:00 servername sssd[nss]: Starting up
Dec  7 08:00:00 servername sssd[sudo]: Starting up
Dec  7 08:00:00 servername sssd[pam]: Starting up

[alexey-tikhonov]

SYSLOG_IDENTIFIER looks weird as well.

@sigv , do I understand correctly actual domain name you are using is different (not EXAMPLE.COM)?
Do you have any special purpose characters in the domain name (say %)?

[sigv]

Indeed, we are not using EXAMPLE.COM and instead have a different domain. That domain is however [A-Z]+.[A-Z]+ such as ABC.DEF. There is nothing weird with regards to any characters, or internationalization (xn-* domains or whatever else).

My simplified sssd.conf which reproduces the issue for me:

[sssd]
  config_file_version = 2
  domains = ABC.DEF
  services =

[nss]

[pam]

[sudo]

[domain/ABC.DEF]
  id_provider = ad
  access_provider = ad
  use_fully_qualified_names = False
  default_shell = /bin/bash
  override_homedir = /home/%d/%u

I do not think further logs are of relevance, but if there is anything I can try collect or test, let me know.

[sigv]

@alexey-tikhonov, do keep in mind, this also seems to affect the other identifiers, such as sudo which does not include the domain itself for example, not only be[*]!

[alexey-tikhonov]

@alexey-tikhonov, do keep in mind, this also seems to affect the other identifiers, such as sudo which does not include the domain itself for example, not only be[*]!

Could you please quote journalctl -o verbose output for those processes?

[sigv]

Example of journalctl -o verbose -u sssd-sudo.service for service start-up:

Mon 2020-12-07 13:03:18.058623 UTC [..]
    SYSLOG_FACILITY=3
    PRIORITY=6
    _UID=0
    _GID=0
    _SELINUX_CONTEXT=unconfined
    _BOOT_ID=317ba63176dc4a308bb54d382a75b382
    _MACHINE_ID=7f8de46959924b8eab671a6af7f41e3f
    _HOSTNAME=servername.example.com
    _CAP_EFFECTIVE=3fffffffff
    SYSLOG_IDENTIFIER=systemd
    _TRANSPORT=journal
    _PID=1
    _COMM=systemd
    _EXE=/usr/lib/systemd/systemd
    _CMDLINE=/sbin/init
    _SYSTEMD_CGROUP=/init.scope
    _SYSTEMD_UNIT=init.scope
    _SYSTEMD_SLICE=-.slice
    CODE_FILE=src/core/job.c
    CODE_LINE=929
    CODE_FUNC=job_log_done_status_message
    JOB_RESULT=done
    UNIT=sssd-sudo.service
    JOB_TYPE=start
    MESSAGE_ID=889671fe2ea2474995771ee867c0cdd2
    MESSAGE=Started SSSD Sudo Service responder.
    JOB_ID=50188
    INVOCATION_ID=098159f0d4054fc693f51ef52fcf56ce
    _SOURCE_REALTIME_TIMESTAMP=1607328000000000

[sigv]

Sorry, the above one was by systemd itself, as it was starting the process. Here is a relevant one:

Mon 2020-12-07 13:03:18.136747 UTC [..]
    SYSLOG_FACILITY=3
    PRIORITY=6
    _UID=0
    _GID=0
    _SELINUX_CONTEXT=unconfined
    _SYSTEMD_SLICE=system.slice
    _BOOT_ID=317ba63176dc4a308bb54d382a75b382
    _MACHINE_ID=7f8de46959924b8eab671a6af7f41e3f
    _HOSTNAME=servername.example.com
    _TRANSPORT=syslog
    _CAP_EFFECTIVE=3fffffffff
    SYSLOG_IDENTIFIER=sssd
    SYSLOG_PID=sudo
    _COMM=sssd_sudo
    _EXE=/usr/libexec/sssd/sssd_sudo
    _CMDLINE=/usr/libexec/sssd/sssd_sudo --socket-activated
    _SYSTEMD_CGROUP=/system.slice/sssd-sudo.service
    _SYSTEMD_UNIT=sssd-sudo.service
    MESSAGE=Starting up
    SYSLOG_TIMESTAMP=Dec  7 13:03:18
    _SYSTEMD_INVOCATION_ID=098159f0d4054fc693f51ef52fcf56ce
    _PID=883569
    _SOURCE_REALTIME_TIMESTAMP=1607328000000000

[alexey-tikhonov]

I can't reproduce this so far.
What version of systemd libs do you have on this system?

[sigv]

This is on an up-to-date Ubuntu 20.04 Focal Server installation.
Will see if I can put together a reproducible case on a fresh VM.

$ systemctl --version
systemd 245 (245.4-4ubuntu3.3)
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid

[alexey-tikhonov]

The thing is, SSSD doesn't set SYSLOG_PID, only SYSLOG_IDENTIFIER:
https://github.com/SSSD/sssd/blob/master/src/util/sss_log.c#L110

In your examples:

    SYSLOG_IDENTIFIER=sssd[be
    SYSLOG_PID=EXAMPLE.COM]

and

    SYSLOG_IDENTIFIER=sssd
    SYSLOG_PID=sudo

it should be SYSLOG_IDENTIFIER=sssd[be[EXAMPLE.COM]] and SYSLOG_IDENTIFIER=sssd[sudo] respectively, and no SYSLOG_PID set.
It works as expected on Fedora.

It seems something on your system treats/parses [*] part of SYSLOG_IDENTIFIER as a PID and puts it to SYSLOG_PID.

[sigv]

Based on a 20.04.1 Server image, fresh installation in a VM including updates.

# apt -qq clean && apt -qqy dist-upgrade
# shutdown -r now

# apt -qqy install sssd
# cat << EOF > /etc/sssd/sssd.conf
[sssd]
  config_file_version = 2
  domains = EXAMPLE.COM
  services = 

[nss]

[pam]

[sudo]

[domain/EXAMPLE.COM]
  id_provider = files
  access_provider = permit
EOF
# chmod 600 /etc/sssd/sssd.conf
# systemctl restart sssd.service

journalctl -u sssd.service lists items such as Dec 07 14:10:00 servername sssd[be[1234]: Starting up

journalctl -o verbose -u sssd-sudo.service still shows items with SYSLOG_PID=sudo

[sigv]

This seems like a fairly minimal example case with no additional integrations from my side.
So potentially the Ubuntu package itself is broken. 😐

[sigv]

This has something to do with Ubuntu 20.04 in particular. That's the current LTS version for Ubuntu, and expected to be the current Server default for one and a half year approximately. I can confirm this by in-place upgrading my VM to Ubuntu 20.10 (Groovy):

# sed -i 's/Prompt=.*/Prompt=normal/' /etc/update-manager/release-upgrades
# do-release-upgrade # <Yes> to everything

# systemctl --version
systemd 246 (246.1-1ubuntu1)
# sssd --version
2.3.1
# apt-cache policy sssd | grep Installed
  Installed: 2.3.1-3

I see only SYSLOG_FACILITY and SYSLOG_IDENTIFIER. There is no SYSLOG_PID no more.

[sigv]

I have to put this on hold for now, but I will get back with information about whether attempting to use SSSD 2.2.3-3 (the Ubuntu 20.04 version) results in broken logging - two scenarios then.

If logs look broken, then the SSSD Ubuntu package on 20.04 is horribly broken.

If logs look fine, then something in Systemd Journald is apparently doing bad parsing on the logs as they pass through, in which case this is actually a kind of an upstream (systemd/journald) issue.

[sigv]

Can't get the 2.2.3-3 source to build on the 20.10 box, without taking a closer look, seems the most likely culprit is incompatible library changes that need some adaptations made. Will just roll back to 20.04 and poke around there, to see if I can get to the root of it. High certainty this will need to be moved over to Launchpad (Ubuntu tracker).

[sigv]

Opened LP: #1908065 on the Ubuntu side.

I will close this ticket as the fix will have to be in the Ubuntu package as a 'stable release update'/SRU with that respective ticket, instead of being handled in the source project here.

[alexey-tikhonov]

Opened LP: #1908065 on the Ubuntu side.

JFTR: imo, this ^^ report doesn't get it right. There is nothing wrong with SSSD package in Ubuntu 20.04 in this aspect. There is something weird with journald that treats part of SYSLOG_IDENTIFIER as SYSLOG_PID. Report doesn't seem to emphasize this.

[sigv]

Sorry, I did comment on that ticket about how systemd is probably to blame here indeed and will update the ticket notes to include that as well. This will probably be moved over to the systemd package on the Ubuntu tracker instead as need be.

[sigv]

A bit of a status update:

Patch has been provided for Ubuntu Focal (20.04) on Ubuntu packaging side, as SSSD 2.2.3-3ubuntu0.4.

The notable change is that --with-syslog=journald has now been added to the configure invocation. Previously, it was depending on the default beavior, which defaulted to using --with-syslog=syslog. The guess then goes that sssd[sudo] was being written to syslog where sudo should be the PID, and journald was trying to parse that in and work with it.

The patch also proposes including commits:

• 00e7b1a - to clean up program names
• 1823353 - to include "sssd[]" identifier in Journald

This was not a problem on the newer Ubuntu versions as those already include --with-syslog=journald.

This could potentially be a problem for other platforms where SSSD is writing to syslog directly, but 1823353 already resolves this concern globally.

[alexey-tikhonov]

Thank you for the update.

[sigv]

A Ubuntu Core Development Team member noted that SSSD should use something other than brackets to avoid Journald producing malformed Syslog output, resulting in PR #5477.