Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.
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 2123637

Summary: Weird "uavc: op=load_policy lsm=selinux seqno=11 res=1" printed to terminal when updating/installing a package
Product: Red Hat Enterprise Linux 9 Reporter: Renaud Métrich <rmetrich>
Component: libselinuxAssignee: Petr Lautrbach <plautrba>
Status: CLOSED WONTFIX QA Contact: Milos Malik <mmalik>
Severity: medium Docs Contact:
Priority: low    
Version: 9.0CC: dwalsh, John.Cronin, kazen, lvrabec, mmalik, plautrba, pmatilai, ssekidde, vmojzis, zpytela
Target Milestone: rcKeywords: Triaged
Target Release: 9.2Flags: pm-rhel: mirror+
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 2123719 (view as bug list) Environment:
Last Closed: 2022-12-19 15:19:40 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 2094166    

Description Renaud Métrich 2022-09-02 09:01:53 UTC
Description of problem:

This seems to apply to RHEL9 only.
When installing or updating a package modifying the policy, the following message is sent to STDERR:
~~~
uavc:  op=load_policy lsm=selinux seqno=XX res=1
~~~

The message is overwritten later by "yum" because the message has no carriage-return.

Digging into this, this message is emitted by avc_process_policyload():
~~~
 79 int avc_process_policyload(uint32_t seqno)
 :
 83         avc_log(SELINUX_POLICYLOAD,
 84                 "%s:  op=load_policy lsm=selinux seqno=%u res=1",
 85                 avc_prefix, seqno);
 :
~~~

which gets called through rpm-plugin-selinux, as seen using a systemtap script:
~~~
# stap -v -d /usr/bin/python3 -d /usr/lib64/libselinux.so.1 -d /usr/lib64/rpm-plugins/selinux.so -d /usr/lib64/librpm.so.9.1.3 -d kernel -d /usr/lib64/python3.9/site-packages/rpm/_rpm.cpython-39-x86_64-linux-gnu.so --ldd -e 'probe syscall.write { if ((fd == 2) && (buf_str =~ "uavc")) { print_usyms(ubacktrace()) } }
[...]

 0x7f0502c2b15f : write+0x4f/0xa0 [/usr/lib64/libc.so.6]
 0x7f0502b831fd : _IO_file_write@@GLIBC_2.2.5+0x2d/0xa0 [/usr/lib64/libc.so.6]
 0x7f0502b82576 : new_do_write+0x66/0x170 [/usr/lib64/libc.so.6]
 0x7f0502b838ce : _IO_file_xsputn@@GLIBC_2.2.5+0x16e/0x1f0 [/usr/lib64/libc.so.6]
 0x7f0502b70a5e : buffered_vfprintf+0x12e/0x230 [/usr/lib64/libc.so.6]
 0x7f05010198fd : default_selinux_log+0xad/0xd0 [/usr/lib64/libselinux.so.1]
 0x7f05010237ae : avc_process_policyload+0xce/0x140 [/usr/lib64/libselinux.so.1]
 0x7f05010313a2 : selinux_status_updated+0xf2/0x150 [/usr/lib64/libselinux.so.1]
 0x7f04fde9d445 : sehandle_init+0xf5/0x120 [/usr/lib64/rpm-plugins/selinux.so]
 0x7f05015fd911 : rpmpsmRun.part.0+0x121/0x1070 [/usr/lib64/librpm.so.9.1.3]
 0x7f050161186e : rpmteProcess+0x1be/0x310 [/usr/lib64/librpm.so.9.1.3]
 0x7f050162b640 : runTransScripts.isra.0+0x40/0x70 [/usr/lib64/librpm.so.9.1.3]
 0x7f0501617a55 : rpmtsRun+0x2a25/0x2cd0 [/usr/lib64/librpm.so.9.1.3]
 0x7f05021d91f8 : rpmts_Run+0xc8/0x140 [...hon3.9/site-packages/rpm/_rpm.cpython-39-x86_64-linux-gnu.so]
 0x7f0502e0eb61 : method_vectorcall_VARARGS_KEYWORDS+0x181/0x1d0 [/usr/lib64/libpython3.9.so.1.0]
 0x7f0502e06129 : _PyEval_EvalFrameDefault+0x5149/0x7a40 [/usr/lib64/libpython3.9.so.1.0]
 0x7f0502e0df33 : function_code_fastcall+0xa3/0x120 [/usr/lib64/libpython3.9.so.1.0]
 0x7f0502e16261 : method_vectorcall+0x81/0x2a0 [/usr/lib64/libpython3.9.so.1.0]
 0x7f0502e06129 : _PyEval_EvalFrameDefault+0x5149/0x7a40 [/usr/lib64/libpython3.9.so.1.0]
 0x7f0502e000dd : _PyEval_EvalCode+0x2dd/0xe40 [/usr/lib64/libpython3.9.so.1.0]
~~~


Version-Release number of selected component (if applicable):

libselinux-3.3-2.el9.x86_64
rpm-plugin-selinux-4.16.1.3-12.el9_0.x86_64

How reproducible:

Always

Steps to Reproduce:
1. Remove "container-selinux" package

  # yum -y remove container-selinux

2. Install "container-selinux" package

  # yum -y install container-selinux

Actual results:

Message printed during scriptlet execution then disappearing

Expected results:

No message (the information about reload is also in the journal because of "dbus-broker"):
~~~
Sep 02 10:52:06 vm-binfmt9 dbus-broker-launch[696]: avc:  op=load_policy lsm=selinux seqno=33 res=1
~~~

Additional info:

Seems new to RHEL8 and doesn't always happen.

Comment 1 Petr Lautrbach 2022-09-02 12:05:23 UTC
There are 2 issues I guess:

1. there's no new line in the message sent to stderr

2. rpm should set a logging callback using selinux_set_callback() if it wants to suppress libselinux to log on stderr, see this simple code:

int func_log(int type, const char *fmt, ...) {
  char *buf;
  va_list ap;

  va_start(ap, fmt);
  vasprintf(&buf, fmt, ap);
  va_end(ap);
  printf("my_logger: %s\n", buf);
  free(buf);
  return 1;
}


int main() {
  union selinux_callback callback;

  selinux_status_open(0);

  selinux_status_updated();
  selinux_mkload_policy(0);
  selinux_status_updated();

  selinux_set_callback(SELINUX_CB_LOG, (union selinux_callback) &func_log);
  selinux_mkload_policy(0);
  selinux_status_updated();
}

Comment 3 John Cronin 2022-09-20 00:53:59 UTC
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

Comment 7 Petr Lautrbach 2022-12-19 15:19:40 UTC
This is being fixed on rpm side. Also, upstream wants to move forward the other way - to drop '\n' from all messages which go through the logging callback as none of consumers - systemd, dbus, dpkg and currently rpm - expect '\n' at the end of messages.