Invalid SYSLOG_PID for (systemd) journal messages

Thank you for taking the time to file a bug report.

I was able to reproduce a similar behavior following the steps you described. I am going to mark this bug as Triaged ans subscribe our team to take a look at it any time soon.

This could also be something on systemd/journald side. Looking at the source code, it seems SYSLOG_IDENTIFIER is the relevant part that gets set, but then somehow ends up 'leaking' into SYSLOG_PID. https://github.com/SSSD/sssd/blob/sssd-2_2_3/src/util/sss_log.c#L110

There is a further upstream commit which amends the SSSD logging mechanism as https://github.com/SSSD/sssd/commit/18233532b72e62452eac6886652fa633ba055d8c and applying this patch on the 2.2.3-3 source appears to make the SYSLOG_PID go away for me. The change itself modifies the format strings. But the resulting SYSLOG_IDENTIFIER still does not seem fully correct, as with the patch applied I see SYSLOG_IDENTIFIER=sssd_be however I would expect to see SYSLOG_IDENTIFIER=sssd[be[EXAMPLE.COM]]. This does further make me lean in the direction of the bug being on systemd, potentially the processing of sd_journal_send, but I do not have experience in debugging the inner workings there.

Is there any way to assist in moving this bug along?

Hi Valters,

This really seems to be a systemd issue: sssd never sets SYSLOG_PID when calling sd_journal_send(), yet journalctl shows e.g. SYSLOG_PID=sudo instead of an empty string. Looks like systemd is mixing the variables or leaking one into the others. The sssd upstream patch you pointed to may act as a partial workaround, but the logging is still odd as you noted.

The sssd upstream devs agree the problem is likely on the systemd side in the bug report you opened [1].

I tried to install systemd and its dependencies from Groovy and Hirsute on a Focal system as a rough way to see if a newer version of systemd fixes the issue, but it kept behaving exactly the same.

I think debugging this requires writing a reproducer in the form of a minimal C program calling sd_journal_send() like sssd does, having it log/set SYSLOG_PID even when it should not.

I'm adding a systemd task to this bug report.

Paride

[1] https://github.com/SSSD/sssd/issues/5431, Dec 15 comment.

sssd is setting SYSLOG_IDENTIFIER to the debug_prg_name internal var, which is set via calls to server_setup(), and in focal (and probably earlier) that's set to a name like "sssd[sudo]". However the syslog MSG section TAG field format requires only alphanumeric characters:
https://tools.ietf.org/html/rfc3164#section-4.1.3

therefore, providing an identifier of "sssd[sudo]" results in the TAG field (indicating the process name) to be "sssd" and "[sudo]" is the start of the CONTENT field. The convention specified in the RFC states that if the CONTENT field starts with "[PID]:" the value contained inside the brackets may be considered the PID, which is exactly what systemd-journald is doing.
https://tools.ietf.org/html/rfc3164#section-5.3

So, when SYSLOG_IDENTIFIER is set to "sssd[sudo]" that results in a syslog message TAG section that's parsed as having program name 'sssd' and pid 'sudo'.

This is fixed upstream in sssd with commit 00e7b1ada3d1c1071eac79b65c17cd2701c2ae6a, included in groovy and later.

It does not appear that systemd-journald is automatically parsing SYSLOG_IDENTIFIER. The following sample program:

#include <systemd/sd-journal.h>

int main(int argc, char *argv[]) {
    sd_journal_send("MESSAGE=%s", "Hello world!",
                    "SYSLOG_IDENTIFIER=%s", "sssd[sudo]",
                    NULL);
}

produces logs with:

    MESSAGE=Hello world!
    SYSLOG_IDENTIFIER=sssd[sudo]

There is no SYSLOG_PID, and SYSLOG_IDENTIFIER is the literal "sssd[sudo]".

/var/log/syslog also contains: "<timestamp> <hostname> sssd[sudo][12345]: Hello world!"

systemd.journal-fields documentation also states the fields are not explicitly validated, so that implies to me no processing on them should be taking place.

Sorry Dan, I did not initially grasp the full implication of your message if it was intended that way. Thank you for the upstream commit linked.

Will poke around a bit more and provide a proposed debdiff to be sponspored then, but to summarize from SSSD side: indeed not reproducible with a minimal C program (and is indeed Status: Invalid for systemd) as the sd_journal_send() branch never actually runs from SSSD side. The rules override_dh_auto_configure does not set --with-syslog=journald in the Focal version, and instead leaves the default --with-syslog=syslog path, indicated by Journald showing _TRANSPORT=syslog as well. That must be where the SYSLOG_PID parsing comes in to play, and that is the reason why the syslog messages are indeed malformed the way they are.

The newer packages (for 20.10 and 21.04) set the Journald logging configuration flag, and have the referenced program name clean-up commit.

The attachment "sssd_2.2.3-3ubuntu0.4.debdiff" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

Thank you for subscribing ubuntu-sponsors.

Feel free to handles this after 2.2.3-3ubuntu0.3 reaches focal-updates, as that was published on focal-proposed yesterday (2021-01-22), and this change is not necessarily of such high priority compared to it.

It seems like to properly fix this and avoid https://github.com/SSSD/sssd/issues/5384 which I think Groovy us affected by, two commits are needed: commit 00e7b1a and commit 1823353. They both seem to have been ported to the sssd-1-16 branch as well.

The Bionic 20.04 debdiff (as 2.2.3-3ubuntu0.4) does include both referenced commits.

I will take a look and provide debdiffs for the other affected versions - Bionic 18.04, Groovy 20.10, Hirsute 21.04.

Sorry, in the last message I meant the Focal 20.04 debdiff includes both.

New revision of sssd_2.3.1-3ubuntu4 debdiff with changes to the patch description, clarifying that the previously referred commit is included in an upstream release already and not a part of the patch series.

For Bionic (18.04) sssd_1.16.1-1ubuntu1.8.debdiff contains rules change (--with-syslog=journald) along with upstream commits 225fe99 and 647a130 (backports for 1.16).

For Focal (20.04) sssd_2.2.3-3ubuntu0.4.debdiff contains rules change (--with-syslog=journald) along with upstream commits 00e7b1a and 1823353.

For Groovy (20.10) sssd_2.3.1-3ubuntu4-2.debdiff contains upstream commit 1823353. The rules already contain the Syslog/Journald override, and upstream commit 00e7b1a has already been included in the original source (as part of v2.3.0).

For Hirsute (21.04) sssd_2.4.0-1ubuntu4.debdiff contains upstream commit 1823353. Rationale is the same as for Groovy.

Bionic and Hirsute do not have anything in -proposed currently.

Focal and Groovy are waiting on LP: #1910611 to be released out from -proposed, and still in need of verification.

> It seems like to properly fix this and avoid https://github.com/SSSD/sssd/issues/5384
> which I think Groovy us affected by, two commits are needed: commit 00e7b1a and commit 1823353.

unfortunately the latter seems to add back in the problematic naming that includes brackets.

Probably someone should explain the problem to upstream sssd and suggest they use something other than brackets; literally anything else should avoid this problem, e.g. parenthesis, curly brackets, etc.

> Probably someone should explain the problem to upstream sssd and suggest they use something other than brackets; literally anything else should avoid this problem, e.g. parenthesis, curly brackets, etc.

This formatting with "[" in syslog TAG is already a concern on Groovy and Hirsute even without that upstream commit. For example, you could see "be[EXAMPLE.COM]" provided as SYSLOG_IDENTIFIER in the upstream 2.3.1 and 2.4.0 versions.

I will take this discussion upstream then.

Opened https://github.com/SSSD/sssd/pull/5477 proposing to replace square brackets with parentheses.

I will wait for review there before proposing new debdiffs with the change, in case either I missed something or upstream wants other tokens than parentheses.

Upstream developers/maintainers opted to remove custom SYSLOG_IDENTIFIER entirely, allowing the program name to be used in place. This avoids having unexpected "[]" in the TAG.

The change is pushed as:
- 01cc267 for main branch (upstream version 2.4.1);
- 360d8fc for version 1.16 backports.

I will prepare debdiffs with the relevant logging changes from upstream.

These latest debdiffs should include all the necessary changes and should be ready for verification, if there are no concerns about the material changes.

To summarize the current proposed changes:

Hirsute (21.04) and Groovy (20.10) receive commmits 1823353 and 01cc267 - one to add "sssd[]" in the right places, and other to stop sending the "sssd[]" as SYSLOG_IDENTIFIER. Both of these commits have already been included in the upstream 2.4.1 release.

Focal (20.04) receives the same commits as well as 00e7b1a before them - to remove excessive "[sssd[]]" wrapping so that adding "sssd[]" in the later commit makes sense. This has already been included in the upstream 2.3.0 release.

Bionic (18.04) receives backports of all three commits Focal receives - 225fe99, 647a130 and 360d8fc. These have not been tagged in the upstream repository with a release tag, however all are included in the sssd-1-16 maintenance branch.

Additionally, both Focal (20.04) and Bionic (18.04) receive --with-syslog=journald flag for configure in rules, so that the native journald sending code branch is used - instead of current default which is sending to syslog, which then gets picked into journald.

Thanks for driving this effort, much appreciated. I can work on properly applying the patches and testing the packages next week (feel free to ping me on IRC if I don't update this bug). I don't know about backporting this to Bionic; it seems that it's not a very urgent issue to justify the update there.

Anyway, I'll keep this on my TODO list for next week. Thanks.

Thank you! Similarly as well - feel free to ping me on IRC in case anything comes up.

@mhodson tagged this as affecting Bionic, so I provided the patch. It has upstream commit tags, highlighting the upstream Git repository has a maintenance branch for 1.16 at https://github.com/SSSD/sssd/commits/sssd-1-16

On my side, we are using Focal in our infra. So I am personally fine with dropping Bionic if it feels like too much effort for the benefit of cleaning up syslog and journald.

I am marking this bug as Won't Fix for Bionic because as far as I could see there is nobody who is affected by this but there. Of course, I am willing to reconsider this decision in case someone shows up and complains about this problem on Bionic.

Hello Valters, or anyone else affected,

Accepted sssd into groovy-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/sssd/2.3.1-3ubuntu4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-groovy to verification-done-groovy. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-groovy. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

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.

The description was updated to reflect changes in the test case for Groovy verification, as the initial test case was valid for Bionic and Focal (already mitigated on Groovy from upstream).

Hello Valters, or anyone else affected,

Accepted sssd into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/sssd/2.2.3-3ubuntu0.4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

This is fixed in Hirsute, which has sssd 2.4.0-1ubuntu3.

The fix for Hirsute is in 2.4.0-1ubuntu4 which did not get pushed further into -release. Currently Hirsute has 2.4.0-1ubuntu5 in -proposed (since Feb 16) with the global archive ownership rebuild.

Performing verification on Focal (20.04)

 # # Install current SSSD from focal-updates (2.2.3-3ubuntu0.3)

 # apt install -y sssd/focal-updates
 # apt policy sssd
sssd:
  Installed: 2.2.3-3ubuntu0.3
  Candidate: 2.2.3-3ubuntu0.3
  Version table:
     2.2.3-3ubuntu0.4 400
        400 http://archive.ubuntu.com/ubuntu focal-proposed/main amd64 Packages
 *** 2.2.3-3ubuntu0.3 500
        500 http://mirrors.digitalocean.com/ubuntu focal-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     2.2.3-3ubuntu0.1 500
        500 http://security.ubuntu.com/ubuntu focal-security/main amd64 Packages
     2.2.3-3 500
        500 http://mirrors.digitalocean.com/ubuntu focal/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=sssd[be

 # journalctl -u sssd.service 'MESSAGE=Starting up'
-- Logs begin at Fri 2021-02-19 18:32:32 UTC, end at Fri 2021-02-19 18:32:39 UTC. --
Feb 19 18:32:39 focal-sssd-test sssd[2712]: Starting up
Feb 19 18:32:39 focal-sssd-test sssd[be[2723]: Starting up

 # grep -E '(sssd|be)[\[\:]' /var/log/syslog
Feb 19 18:32:39 focal-sssd-test sssd: Starting up
Feb 19 18:32:39 focal-sssd-test sssd[be[EXAMPLE.COM]]: 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 focal-proposed (2.2.3-3ubuntu0.4)

 # apt install -y sssd/focal-proposed
 # apt policy sssd
sssd:
  Installed: 2.2.3-3ubuntu0.4
  Candidate: 2.2.3-3ubuntu0.4
  Version table:
 *** 2.2.3-3ubuntu0.4 400
        400 http://archive.ubuntu.com/ubuntu focal-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     2.2.3-3ubuntu0.3 500
        500 http://mirrors.digitalocean.com/ubuntu focal-updates/main amd64 Packages
     2.2.3-3ubuntu0.1 500
        500 http://security.ubuntu.com/ubuntu focal-security/main amd64 Packages
     2.2.3-3 500
        500 http://mirrors.digitalocean.com/ubuntu focal/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 Fri 2021-02-19 18:33:40 UTC, end at Fri 2021-02-19 18:34:00 UTC. --
Feb 19 18:33:58 focal-sssd-test sssd[3170]: Starting up
Feb 19 18:33:58 focal-sssd-test sssd_be[3171]: Starting u

 # grep -E '(sssd|be)[\[\:]' /var/log/syslog
Feb 19 18:33:58 focal-sssd-test sssd[3170]: Starting up
Feb 19 18:33:58 focal-sssd-test sssd_be[3171]: Starting up

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

This bug was fixed in the package sssd - 2.4.0-1ubuntu5

---------------
sssd (2.4.0-1ubuntu5) hirsute; urgency=medium

  * No change rebuild with fixed ownership.

 -- Dimitri John Ledkov <email address hidden> Tue, 16 Feb 2021 15:22:14 +0000

This bug was fixed in the package sssd - 2.3.1-3ubuntu4

---------------
sssd (2.3.1-3ubuntu4) groovy; urgency=medium

  * Avoid sending malformed SYSLOG_IDENTIFIER to journald (LP: #1908065):
    - d/p/lp-1908065-01-syslog_identifier-format.patch:
      Upstream patch to include "sssd[]" identifier in program names.
    - d/p/lp-1908065-02-remove-syslog_identifier.patch:
      Upstream patch to remove custom SYSLOG_IDENTIFIER from Journald.

 -- Valters Jansons <email address hidden> Fri, 05 Feb 2021 16:07:05 +0000

The verification of the Stable Release Update for sssd has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

This bug was fixed in the package sssd - 2.2.3-3ubuntu0.4

---------------
sssd (2.2.3-3ubuntu0.4) focal; urgency=medium

  [ Marco Trevisan ]
  * debian/control:
    - Add missing (test) dependencies as per libcrypto usage (LP: #1905790)
    - Update Maintainer to Ubuntu devs
  * debian/rules: Compile using libcrypto as crypto backend (LP: #1905790)
  * debian/nss-database-pem-exporter: Add to sssd-common and run on postinst.
    When upgrading from previous versions (that were compiled using the NSS
    crypto backend) we need to migrate the trusted CA certificates that the
    user may have added to the SSSD's NSS system database (that defaults to
    /etc/pki/nssdb).
    To do this, and not to introduce a new dependency on libnss3-tools
    (which is not shipped by default, other than making the parsing not
    working in some scenarios) I've added a small C tool that we compile and
    install as part of the sssd-common package which is able to get all the
    trusted CA certificates for a NSS database and export them in PEM
    format.
    The nss-database-pem-exporter is then used in the postinst script where
    we now:
     1. Read the SSSD settings
     2. Convert all the certificates in the configured NSS databases
     3. Store them all, appending them to the (new) default location
        (/etc/sssd/pki/sssd_auth_ca_db.pem)
     4. Disables the configured locations if pointing to NSS dbs (needed or
        we'll leave the configuration with broken values).
    At this point nss-database-pem-exporter is then the only binary in the
    package that still depends on NSS libraries. (LP: #1905790)
  * debian/patches:
    - Get libsofthsm2 from right path for each architecture, this is now used
      for real (wasn't before) to test p11k components with libcrypto and
      p11-kit, also avoids a test build failure on armhf (LP: #1905790)

  [ Valters Jansons ]
  * Avoid sending malformed SYSLOG_IDENTIFIER to journald (LP: #1908065):
    - d/rules: Set --with-syslog=journald in override_dh_auto_configure.
    - d/p/lp-1908065-01-debug_prg_name-format.patch:
      Upstream patch to clean up program names.
    - d/p/lp-1908065-02-syslog_identifier-format.patch:
      Upstream patch to include "sssd[]" identifier in program names.
    - d/p/lp-1908065-03-remove-syslog_identifier.patch:
      Upstream patch to remove custom SYSLOG_IDENTIFIER from Journald.

 -- Marco Trevisan (Treviño) <email address hidden> Thu, 11 Feb 2021 15:31:14 -0500