[Bug 1908065] Re: Invalid SYSLOG_PID for (systemd) journal messages

[Valters Jansons]

Performing verification on Groovy (20.10)

The case for Groovy was removal of multiple square brackets from syslog
output. rsyslog was working with identifiers output such as
`be[DOMAIN.COM][1234]:` which is expected to be seen as `sssd_be[1234]:`
following the change.

 # # Install current SSSD from groovy-updates (2.3.1-3ubuntu3)

 # apt install -y sssd/groovy-updates
 # apt policy sssd
sssd:
  Installed: 2.3.1-3ubuntu3
  Candidate: 2.3.1-3ubuntu3
  Version table:
     2.3.1-3ubuntu4 400
        400 http://archive.ubuntu.com/ubuntu groovy-proposed/main amd64 Packages
 *** 2.3.1-3ubuntu3 500
        500 http://mirrors.digitalocean.com/ubuntu groovy-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     2.3.1-3 500
        500 http://mirrors.digitalocean.com/ubuntu groovy/main amd64 Packages

 # # Set up minimal SSSD.conf

 # 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

 # # Check SSSD logging output

 # journalctl -o verbose -u sssd.service 'MESSAGE=Starting up' | grep SYSLOG_IDENTIFIER=
    SYSLOG_IDENTIFIER=sssd
    SYSLOG_IDENTIFIER=be[EXAMPLE.COM]

 # journalctl -u sssd.service 'MESSAGE=Starting up'
-- Logs begin at Wed 2021-02-17 09:11:49 UTC, end at Wed 2021-02-17 09:17:01 UTC. --
Feb 17 09:12:23 groovy-sssd-test sssd[612]: Starting up
Feb 17 09:12:23 groovy-sssd-test be[EXAMPLE.COM][646]: Starting up

 # grep -E '(sssd|be)\[' /var/log/syslog
Feb 17 09:12:23 groovy-sssd-test sssd[612]: Starting up
Feb 17 09:12:23 groovy-sssd-test be[EXAMPLE.COM][646]: Starting up

 # # Clean up local log output to see only future logs for verification

 # journalctl --rotate && journalctl --vacuum-time=1
 # echo -n '' > /var/log/syslog

 # # In-place upgrade to SSSD from groovy-proposed (2.3.1-3ubuntu4)

 # apt install -y sssd/groovy-proposed
 # apt policy sssd
sssd:
  Installed: 2.3.1-3ubuntu4
  Candidate: 2.3.1-3ubuntu4
  Version table:
 *** 2.3.1-3ubuntu4 400
        400 http://archive.ubuntu.com/ubuntu groovy-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     2.3.1-3ubuntu3 500
        500 http://mirrors.digitalocean.com/ubuntu groovy-updates/main amd64 Packages
     2.3.1-3 500
        500 http://mirrors.digitalocean.com/ubuntu groovy/main amd64 Packages

 # # Check SSSD logging output

 # journalctl -o verbose -u sssd.service 'MESSAGE=Starting up' | grep SYSLOG_IDENTIFIER=
    SYSLOG_IDENTIFIER=sssd
    SYSLOG_IDENTIFIER=sssd_be

 # journalctl -u sssd.service 'MESSAGE=Starting up'
-- Logs begin at Wed 2021-02-17 09:21:39 UTC, end at Wed 2021-02-17 09:22:24 UTC. --
Feb 17 09:22:22 groovy-sssd-test sssd[1340]: Starting up
Feb 17 09:22:22 groovy-sssd-test sssd_be[1341]: Starting up

 # grep -E '(sssd|be)\[' /var/log/syslog
Feb 17 09:22:22 groovy-sssd-test sssd[1340]: Starting up
Feb 17 09:22:22 groovy-sssd-test sssd_be[1341]: Starting up

This verifies the groovy-proposed package fixes the
SYSLOG_IDENTIFIER/rsyslog format bug.

** Tags removed: verification-needed verification-needed-groovy
** Tags added: verification-done verification-done-groovy

-- 
You received this bug notification because you are a member of Ubuntu
Sponsors Team, which is subscribed to the bug report.
https://bugs.launchpad.net/bugs/1908065

Title:
  Invalid SYSLOG_PID for (systemd) journal messages

Status in sssd package in Ubuntu:
  Triaged
Status in sssd source package in Bionic:
  Won't Fix
Status in sssd source package in Focal:
  New
Status in sssd source package in Groovy:
  Fix Committed
Status in sssd source package in Hirsute:
  Triaged

Bug description:
  [Impact]

   * On Ubuntu (Focal) 20.04, SSSD 2.2.3-3, logs in journald have invalid
     (non-numeric) SYSLOG_PID. Any tooling collecting SYSLOG_PID further, or
     attempting to work with syslog directly, fail to parse the PID as number.

   * systemd does not validate, and simply expects SYSLOG_PID as numeric
     integers formatted as decimal strings: https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#SYSLOG_FACILITY=

   * Fixed upstream by https://github.com/SSSD/sssd/commit/00e7b1ada3d1c1071eac79b65c17cd2701c2ae6a
     and https://github.com/SSSD/sssd/commit/18233532b72e62452eac6886652fa633ba055d8c
     and https://github.com/SSSD/sssd/commit/01cc2674959ec249702465621f57259fc779650b

  [Test Case]

   * Deploy fresh 20.04 image, and update:
     apt update && apt dist-upgrade

   * 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 -o verbose -u sssd-sudo.service | grep SYSLOG_PID=
     SYSLOG_PID=sudo

   * journalctl -u sssd.service # Produces malformed example lines:
     Dec 07 14:10:00 servername sssd[be[1234]: Starting up

   * grep sssd /var/log/syslog # Displays non-numeric PIDs:
     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

  [Where problems could occur]

   * Someone might depend on the malformed output already, and have tooling in
     place to transform it manually.

   * Changes to log messages can cause lines to get picked up by things like
     logwatch that weren't before.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/sssd/+bug/1908065/+subscriptions