Bug 2123719

That looks to me like something intended for /var/log/audit/audit.log rather than anybodys stderr, and indeed looking at my own host, such messages can be seen there. Seems the message is just getting "misrouted" someplace.

Rpm has not and does not want anything to do with these logs, including getting callbacks on them. There's already a bug on libselinux to track the issue, closing this one.

libselinux itself logs everything to stderr. It's up to SELinux aware application, in this case selinux plugin in rpm, to re-route messages to a better place if it's necessary. For example see dbus-broker code https://github.com/bus1/dbus-broker/blob/701759a08f5982f515308c269a8e224fc433f4af/src/util/selinux.c#L347

Also there are few hints in SELinux notebook about how to implement SELinux aware application - 
https://github.com/SELinuxProject/selinux-notebook/blob/main/src/implementing_seaware_apps.md#implementing-selinux-aware-applications

    5. The standard output for messages generated by libselinux functions is stderr. Use selinux_set_callback(3) with SELINUX_CB_LOG type to redirect these to a log handler.

This makes no sense to me. Rpm's handling of this hasn't changed at all, and somehow being RHEL 9 specific makes me even more suspicious - again this stuff looks like an audit event destined to audit.log, not your random callback anywhere. From my F36 laptop:

[root@localhost ~]# grep load_policy /var/log/audit/audit.log|tail -3
type=USER_MAC_POLICY_LOAD msg=audit(1659945712.723:502): pid=1282 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  op=load_policy lsm=selinux seqno=4 res=1 exe="/usr/bin/dbus-broker" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
type=USER_MAC_POLICY_LOAD msg=audit(1661323577.794:7063): pid=1321 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  op=load_policy lsm=selinux seqno=2 res=1 exe="/usr/bin/dbus-broker" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
type=USER_MAC_POLICY_LOAD msg=audit(1662098771.841:8641): pid=1321 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  op=load_policy lsm=selinux seqno=3 res=1 exe="/usr/bin/dbus-broker" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"

(In reply to Panu Matilainen from comment #3)
> From my F36 laptop:
> 
> [root@localhost ~]# grep load_policy /var/log/audit/audit.log|tail -3
> type=USER_MAC_POLICY_LOAD msg=audit(1659945712.723:502): pid=1282 uid=81
> auid=4294967295 ses=4294967295
> subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: 
> op=load_policy lsm=selinux seqno=4 res=1 exe="/usr/bin/dbus-broker" sauid=81
> hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
> type=USER_MAC_POLICY_LOAD msg=audit(1661323577.794:7063): pid=1321 uid=81
> auid=4294967295 ses=4294967295
> subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: 
> op=load_policy lsm=selinux seqno=2 res=1 exe="/usr/bin/dbus-broker" sauid=81
> hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"
> type=USER_MAC_POLICY_LOAD msg=audit(1662098771.841:8641): pid=1321 uid=81
> auid=4294967295 ses=4294967295
> subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: 
> op=load_policy lsm=selinux seqno=3 res=1 exe="/usr/bin/dbus-broker" sauid=81
> hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"

This is the result of the code I linked above. dbus-broker sets callback which call utils_audit_log - https://github.com/bus1/dbus-broker/blob/92142f321fc80c76ab1cc973ce2defa1039cac4a/src/util/audit.c#L104

This seems backwards to me: one point of auditing is that stuff gets logged no matter who does it, but in this case it's up to the caller to jump through additional hoops to deliver the message, or ignore it.

Rpm also does *not* load the policy here, it just polls whether it's been updated via selinux_status_updated(). Why should that send such a message? And finally: that selinux_status_updated() call has been in rpm for over a decade. What changed, and why apparently only in RHEL 9?

We are too getting this error with RHEL9 while installing rpm with selinux enabled, this error displayed on terminal, also seen in dmesg.
avc_process_policyload() getting called,

easily reproducible

1. with rpm install.
also with
2.
yum -y remove container-selinux
yum -y install container-selinux

This error not seen with RHEL8/RHEL7

Note that this is does NOT indicate an error, it's just "informative" audit message that the selinux policy got reloaded, ending up in wrong address basically.

After a bit of investigation: this did not happen in older versions simply because said code in libselinux did not exist there, it was added and then changed to current format in these commits: 
https://github.com/SELinuxProject/selinux/commit/a4149e0eab50092699f05217cbf10a60d84d8d20
https://github.com/SELinuxProject/selinux/commit/7ef5b1854f75056d23e60aabc86706dfed622669

So that part of the mystery solved, but : rpm is NOT loading the policy here, it's merely polling to see whether it was. So we're hitting this message because somebody loaded a policy (from the package scriptlet in this case) and rpm - while a transaction running - is interested in tracking whether just that happened.

But okay, actually testing it reveals that the policy load itself does get audited despite rpm not relaying the message anywhere. So it's okay from that POV, all rpm needs is to just set the callback to ignore such output because we're not interested, really.

devel_ack+ for silencing the message.

Oh and as for why I hadn't seen this myself: the message does occur anytime selinux-policies get updated, but dnf progress output masks the line shortly after it appears, so unless you're actually watching dnf output, you'll never see it in the terminal. From the rpm cli it's very obvious.

Thanks. This particular code is not exactly new, it was just refactored. I've been looking into this as well and it's possible that the logging simply should not be there. If you can please hold the PR a bit until I discuss it with libselinux upstream.

Sure. Thanks!

After sleeping a few nights on it, I ended up thinking rpm is better off adding the callback *regardless* of this issue: that way critical libselinux errors get routed to rpmlog as they should. 

I also noticed upstream is reluctant to change it, so lets just add the callback, it's the right thing to do for other reasons. That the "spurious" audit message also gets dealt with is like an added bonus. I'll just adjust the upstream commit message to match this.

Thank You. Debian used the same approach as you did with your PR - https://lore.kernel.org/selinux/20221011160700.82258-1-cgzones@googlemail.com/

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 (rpm 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:2538