Bug 1734723

Summary: pam authentication is slow when nofile is high and selinux enabled
Product: Red Hat Enterprise Linux 7 Reporter: Welterlen Benoit <bwelterl>
Component: pamAssignee: Tomas Mraz <tmraz>
Status: CLOSED ERRATA QA Contact: Dalibor Pospíšil <dapospis>
Severity: high Docs Contact:
Priority: high    
Version: 7.6CC: broose, bwelterl, cbesson, cswanson, dapospis, qguo, rmetrich, suwu, tmraz
Target Milestone: rcKeywords: Reopened, Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: pam-1.1.8-23.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1737812 (view as bug list) Environment:
Last Closed: 2020-03-31 19:10:34 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: 1737812    

Description Welterlen Benoit 2019-07-31 10:02:22 UTC
Description of problem:
pam authentication is slow when nofile limit is high and selinux enabled

Version-Release number of selected component (if applicable):
pam-1.1.8-22.el7.x86_64

How reproducible:
always

Steps to Reproduce:
1. enable selinux
2. set an high nofile limit
3. authenticate through pam

Full steps:
# cat << EOF >/etc/pam.d/check 
auth       required     pam_unix.so
account    required     pam_unix.so
EOF

# ulimit -n
1024
# ./check_user foo
pam_start 1564501527.672
pam_authenticate 1564501527.675
Password: 
pam_acct_mgmt 1564501530.668
ending 1564501530.671
Authenticated
pam_end 1564501530.671

# echo 5242880 >/proc/sys/fs/nr_open
# ulimit -n 5242880
# ./check_user foo
pam_start 1564501568.525
pam_authenticate 1564501568.527
Password: 
pam_acct_mgmt 1564501572.276
ending 1564501573.235
Authenticated
pam_end 1564501573.235

============================================================================================
check_user.c with timestamp in ms
============================================================================================
#include <security/pam_appl.h>
#include <security/pam_misc.h>
#include <stdio.h>
#include <time.h>
#include <inttypes.h>
#include <math.h>

static struct pam_conv conv = {
    misc_conv,
    NULL
};

void timems(char *str)
{
    long            ms; // Milliseconds
    time_t          s;  // Seconds
    struct timespec spec;

    clock_gettime(CLOCK_REALTIME, &spec);

    s  = spec.tv_sec;
    ms = (int)(spec.tv_nsec / 1.0e6); // Convert nanoseconds to milliseconds
    if (ms > 999) {
        s++;
        ms = 0;
    }

    printf("%s %"PRIdMAX".%03ld\n", str, (intmax_t)s, ms);
}

int main(int argc, char *argv[])
{
    pam_handle_t *pamh=NULL;
    int retval;
    const char *user="foo";

    if(argc == 2) {
	user = argv[1];
    }

    if(argc > 2) {
	fprintf(stderr, "Usage: check_user [username]\n");
	exit(1);
    }

    timems("pam_start");

    retval = pam_start("check", user, &conv, &pamh);

    timems("pam_authenticate");
    if (retval == PAM_SUCCESS)
        retval = pam_authenticate(pamh, 0);    /* is user really user? */

    timems("pam_acct_mgmt");
    if (retval == PAM_SUCCESS)
        retval = pam_acct_mgmt(pamh, 0);       /* permitted access? */

    /* This is where we have been authorized or not. */

    timems("ending");
    if (retval == PAM_SUCCESS) {
	fprintf(stdout, "Authenticated\n");
    } else {
	fprintf(stdout, "Not Authenticated\n");
    }

    timems("pam_end");
    if (pam_end(pamh,retval) != PAM_SUCCESS) {     /* close Linux-PAM */
	pamh = NULL;
	fprintf(stderr, "check_user: failed to release authenticator\n");
	exit(1);
    }

    return ( retval == PAM_SUCCESS ? 0:1 );       /* indicate success */
}

Actual results:
- delay in authentication 

Expected results:
- no delay as without selinux or low nofile limit

Additional info:
The pam stack tries to close a lot of FD, from 1 to the nofile limit (or 1999999).
---
...
Bes16324 16:36:25.964912 close(1008)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.964948 close(1009)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.964984 close(1010)       = -1 EBADF (Bad file descriptor) <0.000011>
16324 16:36:25.965020 close(1011)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.965056 close(1012)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.965091 close(1013)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.965128 close(1014)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.965164 close(1015)       = -1 EBADF (Bad file descriptor) <0.000010>
16324 16:36:25.965199 close(1016)       = -1 EBADF (Bad file descriptor) <0.000010>
...
---

This is not visible without selinux enabled.

The source code responsible of that is here:

modules/pam_unix/pam_unix_passwd.c
8<---------- 8< ---------------- 8< ---------------- 8< -------- #ifdef WITH_SELINUX

static int _unix_run_update_binary(pam_handle_t *pamh, unsigned int ctrl, const char *user,
    const char *fromwhat, const char *towhat, int remember) { ...
        if (getrlimit(RLIMIT_NOFILE,&rlim)==0) {
          if (rlim.rlim_max >= MAX_FD_NO)
            rlim.rlim_max = MAX_FD_NO;
          for (i = STDERR_FILENO + 1; i < (int)rlim.rlim_max; i++) {
            if (i != dummyfds[0])
                close(i);
          }
        }
...
8<---------- 8< ---------------- 8< ---------------- 8< --------

There is a BZ that already describe this kind of issue but only with sudo: [sudo 1.8.23 is significantly slower than 1.8.19p2] https://bugzilla.redhat.com/show_bug.cgi?id=1673906

Comment 17 errata-xmlrpc 2020-03-31 19:10:34 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, 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-2020:1005