SSSD rejects LDAP login with su: incorrect password

12,039

Solution 1

It's unsatisfying, but su - leopetr4 and ssh leopetr4@my_hostname started working soon after I set the bounty on the question. I spent some time thinking about why that was without coming to a clear conclusion, as it would be bad for it to stop working as suddenly as it started.

One change I recall making is switching the pam_password setting in /etc/pam_ldap.conf from md5 and exop:

#pam_password md5
pam_password exop

However, the change from broken to working was not immediate, so I hesitate to attribute it to that change.

Solution 2

Sorry that I had to use answer to ask these questions...

What is the output of: authconfig --probe and getent passwd leopetr4

Is your system-auth the same as your password-auth? Can you provide your PAM login file as well?

You may also want to try setting cache_credentials = false in sssd.conf and to clear the cache while testing using sss_cache -E

Share:
12,039

Related videos on Youtube

Leo
Author by

Leo

I’m a Senior Site Reliability Engineer at Autonomic. I do Golang, Ruby, JS, Python, Elixir, as well as web scale devops with Terraform, Ansible, Kubernetes and Docker.

Updated on September 18, 2022

Comments

  • Leo
    Leo over 1 year

    I've set up an LDAP server with user accounts. I've successfully configured a Rails application to authenticate against this LDAP server. I'm now trying to configure SSSD to authenticate against LDAP, but it doesn't like the individual user passwords.

    Error:

    $ su - leopetr4
    Password:
    su: incorrect password
    

    SSSD recognizes the user, but not the password:

    $ id leopetr4
    uid=9583(leopetr4) gid=9583(leopetr4) groups=9583(leopetr4)
    

    Here's what the user record looks like:

    # ldapsearch -x -W -D "cn=admin,dc=my_domain,dc=com"  -H ldaps://my_hostname.my_domain.com "(uid=leopetr4)"
    Enter LDAP Password:
    # extended LDIF
    #
    # LDAPv3
    # base <dc=my_domain,dc=com> (default) with scope subtree
    # filter: (uid=leopetr4)
    # requesting: ALL
    #
    
    # leopetr4, People, my_domain.com
    dn: uid=leopetr4,ou=People,dc=my_domain,dc=com
    uid: leopetr4
    cn: Leo Petr 40
    sn: 40
    objectClass: posixAccount
    objectClass: top
    objectClass: shadowAccount
    objectClass: inetOrgPerson
    shadowLastChange: 16736
    shadowMin: 1
    shadowMax: 99999
    shadowWarning: 7
    loginShell: /bin/bash
    uidNumber: 9583
    gidNumber: 9583
    homeDirectory: /mnt/home/leopetr4
    mail: [email protected]
    gecos: Leo Petr 40
    userPassword:: e1NIQX1vUk5PMWozMXdtdDVIVkVhZmNtNWYvU1Jmam89
    
    # search result
    search: 2
    result: 0 Success
    
    # numResponses: 2
    # numEntries: 1
    

    Here's the user password hash after base64-decoding the above:

    {SHA}oRNO1j31wmt5HVEafcm5f/SRfjo=
    

    It exactly matches the output of slappaswd -c {SHA} "that_password"

    Here's the SSSD config:

    # cat /etc/sssd/sssd.conf
    [sssd]
    config_file_version = 2
    reconnection_retries = 3
    sbus_timeout = 30
    services = nss, pam
    domains = LOCAL,LDAP
    debug_level = 5
    
    [nss]
    filter_groups = root
    filter_users = root
    reconnection_retries = 3
    entry_cache_timeout = 300
    entry_cache_nowait_percentage = 75
    
    [pam]
    reconnection_retries = 3
    offline_credentials_expiration = 2
    offline_failed_login_attempts = 3
    offline_failed_login_delay = 5
    
    [domain/LDAP]
    cache_credentials = true
    
    id_provider = ldap
    auth_provider = ldap
    
    ldap_uri = ldaps://my_hostname.my_domain.com
    ldap_search_base = dc=my_domain,dc=com
    ldap_id_use_start_tls = true
    ldap_tls_reqcert = never
    ldap_tls_cacert = /etc/pki/tls/certs/ca-bundle.crt
    
    debug_level = 5
    

    Here are the SSSD logs when I try to su - leopetr4:

    # tail -f /var/log/secure /var/log/sssd/*.log
    
    ==> /var/log/sssd/sssd_LDAP.log <==
    (Mon Nov 30 12:32:10 2015) [sssd[be[LDAP]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=leopetr4]
    (Mon Nov 30 12:32:10 2015) [sssd[be[LDAP]]] [sdap_save_user] (0x0080): Failed to retrieve UUID [22][Invalid argument].
    (Mon Nov 30 12:32:10 2015) [sssd[be[LDAP]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
    
    ==> /var/log/sssd/sssd.log <==
    (Mon Nov 30 12:32:12 2015) [sssd] [service_send_ping] (0x0100): Pinging LDAP
    (Mon Nov 30 12:32:12 2015) [sssd] [service_send_ping] (0x0100): Pinging nss
    (Mon Nov 30 12:32:12 2015) [sssd] [service_send_ping] (0x0100): Pinging pam
    (Mon Nov 30 12:32:12 2015) [sssd] [ping_check] (0x0100): Service LDAP replied to ping
    (Mon Nov 30 12:32:12 2015) [sssd] [ping_check] (0x0100): Service nss replied to ping
    (Mon Nov 30 12:32:12 2015) [sssd] [ping_check] (0x0100): Service pam replied to ping
    
    ==> /var/log/secure <==
    Nov 30 12:32:12 my_domain su: pam_unix(su-l:auth): authentication failure; logname=root uid=1004 euid=0 tty=pts/3 ruser=leonsp rhost=  user=leopetr4
    
    ==> /var/log/sssd/sssd_LDAP.log <==
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [be_get_account_info] (0x0200): Got request for [0x3][1][name=leopetr4]
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [sdap_save_user] (0x0080): Failed to retrieve UUID [22][Invalid argument].
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [sdap_process_group_send] (0x0040): No Members. Done!
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [sdap_save_group] (0x0080): Failed to retrieve UUID [22][Invalid argument].
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [be_pam_handler] (0x0100): Got request with the following data
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): domain: LDAP
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): user: leopetr4
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): service: su-l
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): tty: pts/3
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): ruser: leonsp
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): rhost:
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): authtok type: 0
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): newauthtok type: 0
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): priv: 0
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): cli_pid: 1586655
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [pam_print_data] (0x0100): logon name: not set
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 7, <NULL>) [Success]
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [be_pam_handler_callback] (0x0100): Sending result [7][LDAP]
    (Mon Nov 30 12:32:12 2015) [sssd[be[LDAP]]] [be_pam_handler_callback] (0x0100): Sent result [7][LDAP]
    
    ==> /var/log/secure <==
    Nov 30 12:32:12 my_domain su: pam_sss(su-l:auth): authentication failure; logname=root uid=1004 euid=0 tty=pts/3 ruser=leonsp rhost= user=leopetr4
    Nov 30 12:32:12 my_domain su: pam_sss(su-l:auth): received for user leopetr4: 7 (Authentication failure)
    

    Here's the LDAP server log when I try to su - leopetr4:

    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: slap_listener_activate(9):
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 busy
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: >>> slap_listener(ldaps:///)
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: listen=9, new connection on 31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: added 31r (active) listener=(nil)
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 fd=31 ACCEPT from IP=256.256.256.256:29338 (IP=0.0.0.0:636)
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 2 descriptors
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:  31r
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: read active on 31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31)
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31): got connid=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): checking for input on id=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:  31r
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: read active on 31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31)
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31): got connid=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): checking for input on id=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): unable to get TLS client DN, error=49 id=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 fd=31 TLS established tls_ssf=256 ssf=256
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:  31r
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: read active on 31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31)
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31): got connid=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): checking for input on id=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: op tag 0x77, time 1448680868
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=0 do_extended
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=0 EXT oid=1.3.6.1.4.1.1466.20037
    Nov 27 21:21:08 my_hostname slapd[15353]: do_extended: oid=1.3.6.1.4.1.1466.20037
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=0 STARTTLS
    Nov 27 21:21:08 my_hostname slapd[15353]: send_ldap_extended: err=1 oid= len=0
    Nov 27 21:21:08 my_hostname slapd[15353]: send_ldap_response: msgid=1 tag=120 err=1
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=0 RESULT oid= err=1 text=TLS already started
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:  31r
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: read active on 31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31)
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_get(31): got connid=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): checking for input on id=3358
    Nov 27 21:21:08 my_hostname slapd[15353]: op tag 0x42, time 1448680868
    Nov 27 21:21:08 my_hostname slapd[15353]: ber_get_next on fd 31 failed errno=0 (Success)
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_read(31): input error=-2 id=3358, closing.
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_closing: readying conn=3358 sd=31 for close
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_close: deferring conn=3358 sd=31
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=1 do_unbind
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 op=1 UNBIND
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_resched: attempting closing conn=3358 sd=31
    Nov 27 21:21:08 my_hostname slapd[15353]: connection_close: conn=3358 sd=31
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: removing 31
    Nov 27 21:21:08 my_hostname slapd[15353]: conn=3358 fd=31 closed
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:08 my_hostname slapd[15353]:
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:08 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: activity on 1 descriptor
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: activity on:
    Nov 27 21:21:09 my_hostname slapd[15353]:  26r
    Nov 27 21:21:09 my_hostname slapd[15353]:
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: read active on 26
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: epoll: listen=7 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: epoll: listen=8 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: epoll: listen=10 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: daemon: epoll: listen=11 active_threads=0 tvp=NULL
    Nov 27 21:21:09 my_hostname slapd[15353]: connection_get(26)
    Nov 27 21:21:09 my_hostname slapd[15353]: connection_get(26): got connid=3331
    Nov 27 21:21:09 my_hostname slapd[15353]: connection_read(26): checking for input on id=3331
    Nov 27 21:21:09 my_hostname slapd[15353]: op tag 0x63, time 1448680869
    Nov 27 21:21:09 my_hostname slapd[15353]: conn=3331 op=122 do_search
    Nov 27 21:21:09 my_hostname slapd[15353]: >>> dnPrettyNormal: <dc=my_domain,dc=com>
    Nov 27 21:21:09 my_hostname slapd[15353]: <<< dnPrettyNormal: <dc=my_domain,dc=com>, <dc=my_domain,dc=com>
    Nov 27 21:21:09 my_hostname slapd[15353]: SRCH "dc=my_domain,dc=com" 2 0
    Nov 27 21:21:09 my_hostname slapd[15353]:     0 0 0
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: AND
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter_list
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: EQUALITY
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: EQUALITY
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: AND
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter_list
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: PRESENT
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: NOT
    Nov 27 21:21:09 my_hostname slapd[15353]: begin get_filter
    Nov 27 21:21:09 my_hostname slapd[15353]: EQUALITY
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter_list
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter_list
    Nov 27 21:21:09 my_hostname slapd[15353]: end get_filter 0
    Nov 27 21:21:09 my_hostname slapd[15353]:     filter: (&(uid=leopetr4)(objectClass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))
    Nov 27 21:21:09 my_hostname slapd[15353]:     attrs:
    Nov 27 21:21:09 my_hostname slapd[15353]:  objectClass
    Nov 27 21:21:09 my_hostname slapd[15353]:  uid
    Nov 27 21:21:09 my_hostname slapd[15353]:  userPassword
    Nov 27 21:21:09 my_hostname slapd[15353]:  uidNumber
    Nov 27 21:21:09 my_hostname slapd[15353]:  gidNumber
    Nov 27 21:21:09 my_hostname slapd[15353]:  gecos
    Nov 27 21:21:09 my_hostname slapd[15353]:  homeDirectory
    Nov 27 21:21:09 my_hostname slapd[15353]:  loginShell
    Nov 27 21:21:09 my_hostname slapd[15353]:  krbPrincipalName
    Nov 27 21:21:09 my_hostname slapd[15353]:  cn
    Nov 27 21:21:09 my_hostname slapd[15353]:  modifyTimestamp
    Nov 27 21:21:09 my_hostname slapd[15353]:  modifyTimestamp
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowLastChange
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowMin
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowMax
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowWarning
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowInactive
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowExpire
    Nov 27 21:21:09 my_hostname slapd[15353]:  shadowFlag
    Nov 27 21:21:09 my_hostname slapd[15353]:  krbLastPwdChange
    Nov 27 21:21:09 my_hostname slapd[15353]:  krbPasswordExpiration
    Nov 27 21:21:09 my_hostname slapd[15353]:  pwdAttribute
    Nov 27 21:21:09 my_hostname slapd[15353]:  authorizedService
    Nov 27 21:21:09 my_hostname slapd[15353]:  accountExpires
    Nov 27 21:21:09 my_hostname slapd[15353]:  userAccountControl
    Nov 27 21:21:09 my_hostname slapd[15353]:  nsAccountLock
    Nov 27 21:21:09 my_hostname slapd[15353]:  host
    Nov 27 21:21:09 my_hostname slapd[15353]:  loginDisabled
    Nov 27 21:21:09 my_hostname slapd[15353]:  loginExpirationTime
    Nov 27 21:21:09 my_hostname slapd[15353]:  loginAllowedTimeMap
    Nov 27 21:21:09 my_hostname slapd[15353]:  sshPublicKey
    Nov 27 21:21:09 my_hostname slapd[15353]:
    Nov 27 21:21:09 my_hostname slapd[15353]: conn=3331 op=122 SRCH base="dc=my_domain,dc=com" scope=2 deref=0 filter="(&(uid=leopetr4)(objectClass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))"
    Nov 27 21:21:09 my_hostname slapd[15353]: conn=3331 op=122 SRCH attr=objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn modifyTimestamp modifyTimestamp shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdAttribute authorizedService accountExpires userAccountControl nsAccountLock host loginDisabled loginExpirationTime loginAllowedTimeMap sshPublicKey
    Nov 27 21:21:09 my_hostname slapd[15353]: ==> limits_get: conn=3331 op=122 self="[anonymous]" this="dc=my_domain,dc=com"
    Nov 27 21:21:09 my_hostname slapd[15353]: => hdb_search
    

    Edit: Here's /var/log/secure for a login attempt:

    Nov 28 13:09:10 my_hostname su: pam_unix(su-l:auth): authentication failure; logname=root uid=1004 euid=0 tty=pts/1 ruser=leonsp rhost=  user=leopetr4
    Nov 28 13:09:10 my_hostname su: pam_sss(su-l:auth): authentication failure; logname=root uid=1004 euid=0 tty=pts/1 ruser=leonsp rhost= user=leopetr4
    Nov 28 13:09:10 my_hostname su: pam_sss(su-l:auth): received for user leopetr4: 7 (Authentication failure)
    

    Here's the pam configuration:

    # cat /etc/pam.d/system-auth
    #%PAM-1.0
    # This file is auto-generated.
    # User changes will be destroyed the next time authconfig is run.
    auth        required      pam_env.so
    auth        sufficient    pam_fprintd.so
    auth        sufficient    pam_unix.so nullok try_first_pass
    auth        requisite     pam_succeed_if.so uid >= 500 quiet
    auth        sufficient    pam_sss.so use_first_pass
    auth        sufficient    pam_ldap.so use_first_pass
    auth        required      pam_deny.so
    
    account     required      pam_unix.so broken_shadow
    account     sufficient    pam_localuser.so
    account     sufficient    pam_succeed_if.so uid < 500 quiet
    account     [default=bad success=ok user_unknown=ignore] pam_sss.so
    account     [default=bad success=ok user_unknown=ignore] pam_ldap.so
    account     required      pam_permit.so
    
    password    requisite     pam_cracklib.so try_first_pass retry=3 minlen=8 dcredit=-1 ucredit=0 lcredit=-1 ocredit=0 type= reject_username
    password    sufficient    pam_unix.so sha512 shadow nullok try_first_pass use_authtok
    password    sufficient    pam_sss.so use_authtok
    password    sufficient    pam_ldap.so use_authtok
    password    required      pam_deny.so
    
    session     optional      pam_keyinit.so revoke
    session     required      pam_limits.so
    session     optional      pam_mkhomedir.so umask=0077
    session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
    session     required      pam_unix.so
    session     optional      pam_sss.so
    session     optional      pam_ldap.so
    

    PAM LDAP config:

    # cat /etc/pam_ldap.conf | grep -v '^#' | grep -v '^$'
    base dc=my_domain,dc=com
    uri ldaps://my_hostname.my_domain.com
    ssl start_tls
    tls_cacertdir /etc/openldap/cacerts
    pam_password md5
    

    Also:

    # authconfig --test | grep hashing
     password hashing algorithm is sha512
    

    Edit 2: Authentication via pamtester works, but it continues to not work via su:

    [leonsp@my_hostname ~]$ pamtester login leopetr4 authenticate
    Password:
    pamtester: successfully authenticated
    
    [leonsp@my_hostname ~]$ pamtester su leopetr4 authenticate
    Password:
    pamtester: Authentication failure
    
    [leonsp@my_hostname ~]$ pamtester su-l leopetr4 authenticate
    Password:
    pamtester: successfully authenticated
    
    1. Why isn't SSSD letting me log in as this user?

    2. Is there something I need to do to configure SSSD to match basic {SHA} hashes?

    3. How do I figure out the difference between authenticating for login and authenticating for su/su-l?

    • jhrozek
      jhrozek over 8 years
      According to the sssd logs, sssd both authenticated you and then allowed access. I would look into the /var/log/secure file or equivalent on your distribution to see what PAM messages there are and if there is maybe another PAM module acting up. btw using tls_reqcert=never is not a good idea, because then even certificates not trusted by your CA would be allowed. Oh and finally wrong password message by su can mean anything - that's just the default error message the utility has.
    • Leo
      Leo over 8 years
      @jhrozek I've added /var/log/secure and pam configuration details to the question
    • jhrozek
      jhrozek over 8 years
      Can you also edit the question so that the logs also capture the authentication failure? Because even though the /var/log/secure shows auth failure, the sssd_be logs show success: (Fri Nov 27 21:15:54 2015) [sssd[be[LDAP]]] [be_pam_handler_callback] (0x0100): Sent result [0][LDAP] Can you please edit the files so that the same PAM login is captured and also the PAM responder logs are there?
    • Leo
      Leo over 8 years
      @jhrozek I've recaptured /var/log/secure and /var/log/sssd/*.log output for su - leopetr4.
  • Leo
    Leo over 8 years
    Per my answer, the error went away and it started working without an immediately clear reason. authconfig --probe has no output and getent passwd leopetr4 outputs leopetr4:*:9583:9583:Leo Petr 40:/mnt/home/leopetr4:/bin/bash