RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2129015 - PID logging oddity
Summary: PID logging oddity
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 9
Classification: Red Hat
Component: rsyslog
Version: 9.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Attila Lakatos
QA Contact: Dalibor Pospíšil
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-09-22 09:59 UTC by Marko Myllynen
Modified: 2023-11-07 09:49 UTC (History)
4 users (show)

Fixed In Version: rsyslog-8.2102.0-115.el9
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-11-07 08:33:06 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
journalctl output (311.62 KB, text/plain)
2022-09-22 09:59 UTC, Marko Myllynen
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github rsyslog rsyslog pull 5010 0 None open imjournal: add second fallback to the message identifier 2022-11-01 06:58:55 UTC
Red Hat Issue Tracker RHELPLAN-134671 0 None None None 2022-09-22 10:11:38 UTC
Red Hat Issue Tracker SECENGSP-4810 0 None None None 2022-09-26 09:06:16 UTC
Red Hat Product Errata RHBA-2023:6444 0 None None None 2023-11-07 08:33:22 UTC

Description Marko Myllynen 2022-09-22 09:59:08 UTC
Created attachment 1913478 [details]
journalctl output

Description of problem:
Journal shows this on RHEL 9:

Sep 22 08:02:42 localhost systemd[1527]: Started GNOME Shell on X11.
Sep 22 08:02:42 localhost gnome-shell[2202]: Adding device '/dev/dri/card0' (i915) using atomic mode setting.
Sep 22 08:02:43 mars gnome-shell[2202]: Boot VGA GPU /dev/dri/card0 selected as primary

Meaning that gnome-shell is running as PID 2022 and all the references to PID 2202 in the journal are related to gnome-shell. But in /var/log/messages we see:

Sep 22 08:02:42 localhost journal[2202]: Adding device '/dev/dri/card0' (i915) using atomic mode setting.
Sep 22 08:02:43 localhost journal[2202]: Boot VGA GPU /dev/dri/card0 selected as primary
...
Sep 22 08:07:00 localhost gnome-shell[2202]: Window manager warning: W4 appears to be one of the offending windows with a timestamp of 275728.  Working around...

So in /var/log/messages PID 2202 is referring to both journal and gnome-shell, although much more often to journal.

I'm attaching "/usr/bin/journalctl -o verbose _PID=2202" output to show how the message metadata looks like.

This is seen on my laptop which is rebooted every morning and I see this happening every day. Thanks.

Version-Release number of selected component (if applicable):
systemd-250-6.el9_0.1.x86_64
gnome-shell-40.9-2.el9.x86_64

Comment 1 Zbigniew Jędrzejewski-Szmek 2022-09-22 11:30:22 UTC
Oh, so I misunderstood. I thought 'journalctl' was giving the wrong output, but it's
actually in the text logs. Most likely this has nothing to do with systemd.

Comment 2 Attila Lakatos 2022-09-26 08:51:24 UTC
Hello,

I assume that you are using the imjournal module to load logs from the journal.
After analyzing the journal output you provided I can see two different kinds of logs:

The first one has identifier as "journal":
Sep 22 08:02:43 localhost journal[2202]: Boot VGA GPU /dev/dri/card0 selected as primary
with metadata: _COMM=gnome-shell
               SYSLOG_IDENTIFIER is NOT specified

The second one has identifier as "gnome-shell":
Sep 22 08:07:00 localhost gnome-shell[2202]: Window manager warning: W4 appears to be one of the offending windows with a timestamp of 275728.
with metadata: _COMM=gnome-shell
               SYSLOG_IDENTIFIER=gnome-shell

As you can see the SYSLOG_IDENTIFIER might be the difference here. Rsyslog does not work with the journals directly, instead we use the journal API. Whatever is passed through the API we display it according to a certain template. Thus, this is not a bug on the rsyslog side.
Let me know what you think. Thanks.

Comment 3 Zbigniew Jędrzejewski-Szmek 2022-09-26 09:12:17 UTC
This description seems correct, except for the conclusions. As you note, the journal API is used,
which means that rsyslog has access to the same information that the journalctl client does.
The way that the entry looks is under rsyslog's control, being the result of the template used.

Comment 4 Attila Lakatos 2022-09-27 07:31:32 UTC
This is how the identifier is created:

if (journalGetData("SYSLOG_IDENTIFIER", &get, &length) >= 0) {
	CHKiRet(sanitizeValue(((const char *)get) + 18, length - 18, &sys_iden));
} else {
	CHKmalloc(sys_iden = strdup("journal"));
}

So the "journal" field in the message is treated as a fallback. Another thing that I observed from the provided logs is that there is a difference between the used transport method:
 * the first one is received via the native journal protocol(_TRANSPORT=journal)
 * the second one is received from a services's standard output or error output (_TRANSPORT=stdout)
I think the client should provide the SYSLOG_IDENTIFIER field.

If you would like to add the name of the command that invoked the message, then you can do that by specifying a custom template. Every single journal field is stored in a JSON object of the message. If you want to know what journal fields are available to you, then write out the message using the RSYSLOG_DebugFormat template, e.g.: *.* action(type="omfile" File="/var/log/test.log" Template="RSYSLOG_DebugFormat") and you will get something like:

$!:{ "PRIORITY": "6", "_BOOT_ID": "3895bc9247a64d8bbbd982a4e96bbbbb", "_MACHINE_ID": "77f6a405c2a74b63b06593a959555", "_HOSTNAME": "localhost.localdomain", "_TRANSPORT": "syslog", "_COMM": "logger", "_SELINUX_CONTEXT": "unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023", "_GID": "1000", "_UID": "1000", "SYSLOG_IDENTIFIER": "alakatos", "SYSLOG_FACILITY": "22", "SYSLOG_TIMESTAMP": "Sep 27 09:22:29 ", "MESSAGE": "My message 1", "_PID": "14999", "_SOURCE_REALTIME_TIMESTAMP": "1664263349893412" }

These fields are available and you can display as many of them as you would like.

Comment 5 Zbigniew Jędrzejewski-Szmek 2022-09-27 08:42:18 UTC
Righto. So "journal" is not a very good fallback. Journalctl uses the following logic:
 
        PARSE_FIELD_VEC_ENTRY("SYSLOG_IDENTIFIER=", &identifier, &identifier_len),
        PARSE_FIELD_VEC_ENTRY("_COMM=", &comm, &comm_len),
        ...

        if (mode == OUTPUT_WITH_UNIT && ...) {
                /* Not interesting for rsyslog I guess */

        } else if (identifier && shall_print(identifier, identifier_len, flags)) {
                fprintf(f, " %.*s", (int) identifier_len, identifier);
                n += identifier_len + 1;
        } else if (comm && shall_print(comm, comm_len, flags)) {
                fprintf(f, " %.*s", (int) comm_len, comm);
                n += comm_len + 1;
        } else
                fputs(" unknown", f);

In other words, it uses SYSLOG_IDENTIFIER and falls back to _COMM.

Comment 6 Attila Lakatos 2022-09-27 08:55:13 UTC
That makes sense. Thanks for the detailed report. Let me take the issue upstream what they think about this.

Comment 7 Attila Lakatos 2022-11-01 06:58:56 UTC
Attached upstream pull request.

Comment 20 errata-xmlrpc 2023-11-07 08:33:06 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (rsyslog bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:6444


Note You need to log in before you can comment on or make changes to this bug.