[Sssd-maintainers] [Bug 2088481] New: selinux_child: Cannot beign SELinux transaction

https://bugzilla.redhat.com/show_bug.cgi?id=2088481

            Bug ID: 2088481
           Summary: selinux_child: Cannot beign SELinux transaction
           Product: Fedora
           Version: 34
            Status: NEW
         Component: sssd
          Assignee: sssd-maintainers(a)lists.fedoraproject.org
          Reporter: rcritten(a)redhat.com
        QA Contact: extras-qa(a)fedoraproject.org
                CC: abokovoy(a)redhat.com, atikhono(a)redhat.com,
                    jhrozek(a)redhat.com, lslebodn(a)redhat.com,
                    luk.claes(a)gmail.com, mzidek(a)redhat.com,
                    pbrezina(a)redhat.com, sbose(a)redhat.com,
                    ssorce(a)redhat.com,
                    sssd-maintainers(a)lists.fedoraproject.org
  Target Milestone: ---
    Classification: Fedora



Description of problem:

Some logins fail under load due to contention over the SELinux transaction lock
in libsemanage.

I'm trying to gather scalability information on IPA. The test revolves around
bringing up a number of client VMs, enrolling as IPA clients and running a
forking client that does a PAM transaction with the login service. Each client
has a set of unique users with non-expired passwords to authenticate with. No
pre-loading of the cache is done.

In this particular case I brought up 10 clients and ran the test tool do to 10
logins. All of these 100 logins happen more or less simultaneously (time is
synced). 30 of the authentications failed due to the transaction locking.

IPA should be able to handle 100 authentications without breaking a sweat and
the server-side logs don't show any issues but it may be somewhat load related.
If I re-run the test tool after the fact, even clearing the SSSD cache I can't
reproduce the transaction failure.

I wonder if a retry could be implemented.

The selinux_child log contains the following. It is consistent across all the
clients (log level 3):

(2022-05-19 13:42:01): [selinux_child[11668]] [libsemanage] (0x0020): Could not
get direct transaction lock at /var/lib/selinux/targeted/semanage.trans.LOCK.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [main] (0x0400):
selinux_child started.
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [main] (0x2000): Running
with effective IDs: [0][0].
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [main] (0x2000): Running
with real IDs [0][0].
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [main] (0x0400): context
initialized
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
seuser length: 12
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
seuser: unconfined_u
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
mls_range length: 14
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
mls_range: s0-s0:c0.c1023
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
username length: 23
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [unpack_buffer] (0x2000):
username: user6client000.ipa.test
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [main] (0x0400): performing
selinux operations
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [seuser_needs_update]
(0x2000): sss_get_seuser: ret: 0 seuser: unconfined_u mls: s0-s0:c0.c1023
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [sss_seuser_exists]
(0x0400): seuser exists: no
   *  (2022-05-19 13:41:56): [selinux_child[11668]] [seuser_needs_update]
(0x0400): The SELinux user does need an update
   *  (2022-05-19 13:42:01): [selinux_child[11668]] [libsemanage] (0x0020):
Could not get direct transaction lock at
/var/lib/selinux/targeted/semanage.trans.LOCK.
********************** BACKTRACE DUMP ENDS HERE
*********************************

(2022-05-19 13:42:01): [selinux_child[11668]] [sss_set_seuser] (0x0020): Cannot
begin SELinux transaction
(2022-05-19 13:42:01): [selinux_child[11668]] [main] (0x0020): Cannot set
SELinux login context.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
   *  (2022-05-19 13:42:01): [selinux_child[11668]] [sss_set_seuser] (0x0020):
Cannot begin SELinux transaction
   *  (2022-05-19 13:42:01): [selinux_child[11668]] [main] (0x0020): Cannot set
SELinux login context.
********************** BACKTRACE DUMP ENDS HERE
*********************************

(2022-05-19 13:42:01): [selinux_child[11668]] [main] (0x0020): selinux_child
failed!
(2022-05-19 13:42:01): [selinux_child[11671]] [libsemanage] (0x0020): Could not
get direct transaction lock at /var/lib/selinux/targeted/semanage.trans.LOCK.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [main] (0x0400):
selinux_child started.
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [main] (0x2000): Running
with effective IDs: [0][0].
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [main] (0x2000): Running
with real IDs [0][0].
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [main] (0x0400): context
initialized
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
seuser length: 12
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
seuser: unconfined_u
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
mls_range length: 14
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
mls_range: s0-s0:c0.c1023
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
username length: 23
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [unpack_buffer] (0x2000):
username: user1client000.ipa.test
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [main] (0x0400): performing
selinux operations
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [seuser_needs_update]
(0x2000): sss_get_seuser: ret: 0 seuser: unconfined_u mls: s0-s0:c0.c1023
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [sss_seuser_exists]
(0x0400): seuser exists: no
   *  (2022-05-19 13:41:56): [selinux_child[11671]] [seuser_needs_update]
(0x0400): The SELinux user does need an update
   *  (2022-05-19 13:42:01): [selinux_child[11671]] [libsemanage] (0x0020):
Could not get direct transaction lock at
/var/lib/selinux/targeted/semanage.trans.LOCK.
********************** BACKTRACE DUMP ENDS HERE
*********************************

(2022-05-19 13:42:01): [selinux_child[11671]] [sss_set_seuser] (0x0020): Cannot
begin SELinux transaction
(2022-05-19 13:42:01): [selinux_child[11671]] [main] (0x0020): Cannot set
SELinux login context.
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
   *  (2022-05-19 13:42:01): [selinux_child[11671]] [sss_set_seuser] (0x0020):
Cannot begin SELinux transaction
   *  (2022-05-19 13:42:01): [selinux_child[11671]] [main] (0x0020): Cannot set
SELinux login context.
********************** BACKTRACE DUMP ENDS HERE
*********************************

(2022-05-19 13:42:01): [selinux_child[11671]] [main] (0x0020): selinux_child
failed!

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

sssd-common-2.5.2-2.fc34


-- 
You are receiving this mail because:
You are the assignee for the bug.
You are on the CC list for the bug.
https://bugzilla.redhat.com/show_bug.cgi?id=2088481