libpam-ldap unable to connect to LDAP server over SSL/TLS

Question

I am trying to configure PAM to work with my LDAP server for authentication. To do this I am trying to use libpam-ldap, I decided to use libpam-ldap instead of libpam-ldapd for two reasons. First, libpam-ldapd doesn't appear to support group based authentication, meaning I wouldn't be able to control what users have access to what services using LDAP groups (at least for services using PAM), and second when I tried installing libpam-ldapd the entire server became extremely unresponsive, taking upwards of 30 seconds to process commands.

When an authentication attempt is made, libpam_ldap correctly attempts to contact the desired LDAP server on port 636, however no bind attempt is made. Reconfiguring libpam-ldap to connect to the LDAP server over a non-TLS connection over port 389 results in a bind attempt that is correctly rejected by my LDAP server's policy for authentication on non-TLS connections.

I am running Debian 10.4, and my pam_ldap.conf file (which as part of my troubleshooting process I have stripped down to a minimal configuration) is as follows

base ou=people,dc=example,dc=com
uri ldaps://example.com/
ldap_version 3
binddn uid=0,ou=servers,dc=example,dc=com
bindpw mypassword
pam_login_attribute displayName
pam_password clear
ssl on
tls_checkpeer no
tls_cacertdir /etc/ssl/certs
logdir /var/log/pamldap

Everywhere where it says example the actual config has the correct value. Passwords are set to clear because password hashing is being handled server side by ppolicy. The options specifying "ssl on", as well as "tls_checkpeer", and "tls_cacertdir" are all included as part of my troubleshooting process, and no combination of them results in a successful connection to the LDAP server.

The logdir flag in the config does not work, so libpam-ldap produces no logs which has severely complicated troubleshooting. So far troubleshooting has consisted of attempting to authenticate an FTP user, and monitoring the logs on the LDAP server as well as what information is propagated to the FTP client. Attempting to log in while libpam-ldap is configured to use TLS results in the FTP client timing out, and the following log on the LDAP server

Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: slap_listener_activate(8):
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 busy
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: >>> slap_listener(ldaps:///)
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: listen=8, new connection on 12
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]: daemon: added 12r (active) listener=(nil)
Jun  4 15:11:05 MyServer slapd[831]:  12r
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: read active on 12
Jun  4 15:11:05 MyServer slapd[831]: conn=1000 fd=12 ACCEPT from IP=X.X.X.X:1025 (IP=0.0.0.0:636)
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12)
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12): got connid=1000
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: connection_read(12): checking for input on id=1000
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:  12r
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: read active on 12
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12)
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12): got connid=1000
Jun  4 15:11:05 MyServer slapd[831]: connection_read(12): checking for input on id=1000
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:  12r
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: read active on 12
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12)
Jun  4 15:11:05 MyServer slapd[831]: connection_get(12): got connid=1000
Jun  4 15:11:05 MyServer slapd[831]: connection_read(12): checking for input on id=1000
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on 1 descriptor
Jun  4 15:11:05 MyServer slapd[831]: daemon: activity on:
Jun  4 15:11:05 MyServer slapd[831]:
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:11:05 MyServer slapd[831]: daemon: epoll: listen=10 active_threads=0 tvp=zero

Attempting to log in over an unencrypted connection results in the FTP client being passed a 530 login incorrect response and a "Critical error: Could not connect to server" error message, and the following log being recorded by the LDAP server

Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: slap_listener_activate(8):
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 busy
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: >>> slap_listener(ldap:///)
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: listen=8, new connection on 14
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]:  14r
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: added 14r (active) listener=(nil)
Jun  4 15:27:20 MyServer slapd[5866]: daemon: read active on 14
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 fd=14 ACCEPT from IP=X.X.X.X:47982 (IP=0.0.0.0:389)
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: connection_get(14)
Jun  4 15:27:20 MyServer slapd[5866]: connection_get(14): got connid=1002
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: connection_read(14): checking for input on id=1002
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]: op tag 0x60, time 1591298840
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 op=0 do_bind
Jun  4 15:27:20 MyServer slapd[5866]: >>> dnPrettyNormal: <uid=0,ou=servers,dc=example,dc=com>
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: <<< dnPrettyNormal: <uid=0,ou=servers,dc=example,dc=com>, <uid=0,ou=servers,dc=example,dc=com>
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 op=0 BIND dn="uid=0,ou=servers,dc=example,dc=com" method=128
Jun  4 15:27:20 MyServer slapd[5866]: do_bind: version=3 dn="uid=0,ou=servers,dc=example,dc=com" method=128
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: send_ldap_result: conn=1002 op=0 p=3
Jun  4 15:27:20 MyServer slapd[5866]: send_ldap_result: err=13 matched="" text="confidentiality required"
Jun  4 15:27:20 MyServer slapd[5866]: send_ldap_response: msgid=1 tag=97 err=13
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 op=0 RESULT tag=97 err=13 text=confidentiality required
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]:  14r
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: read active on 14
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: connection_get(14)
Jun  4 15:27:20 MyServer slapd[5866]: connection_get(14): got connid=1002
Jun  4 15:27:20 MyServer slapd[5866]: connection_read(14): checking for input on id=1002
Jun  4 15:27:20 MyServer slapd[5866]: op tag 0x42, time 1591298840
Jun  4 15:27:20 MyServer slapd[5866]: ber_get_next on fd 14 failed errno=0 (Success)
Jun  4 15:27:20 MyServer slapd[5866]: connection_read(14): input error=-2 id=1002, closing.
Jun  4 15:27:20 MyServer slapd[5866]: connection_closing: readying conn=1002 sd=14 for close
Jun  4 15:27:20 MyServer slapd[5866]: connection_close: deferring conn=1002 sd=14
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on 1 descriptor
Jun  4 15:27:20 MyServer slapd[5866]: daemon: activity on:
Jun  4 15:27:20 MyServer slapd[5866]:
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 op=1 do_unbind
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 op=1 UNBIND
Jun  4 15:27:20 MyServer slapd[5866]: daemon: epoll: listen=12 active_threads=0 tvp=zero
Jun  4 15:27:20 MyServer slapd[5866]: connection_resched: attempting closing conn=1002 sd=14
Jun  4 15:27:20 MyServer slapd[5866]: connection_close: conn=1002 sd=14
Jun  4 15:27:20 MyServer slapd[5866]: daemon: removing 14
Jun  4 15:27:20 MyServer slapd[5866]: conn=1002 fd=14 closed

Which appears to be the correct policy reponse for my LDAP server.

To clarify my issue: libpam_ldap is unable to communicate with my LDAP server over TLS, can anyone tell me why this is the case and what I need to do to fix this issue. If you do not think this is the issue I am having, what do you beleive the issue is, and what do you think I need to do to fix that issue?

score 0 · Accepted Answer · answered Jun 08 '20 at 02:37

I have finally figured out my problem. My problem is a weird TLS problem wherein if you try to establish a TLS connection from a machine to itself across NAT (the LDAP server and client are on the same machine, but in order for TLS to work properly the client needs to connect via the domain name, and therefore must traverse NAT), the connection just flat out doesn't work. This is not exclusive to LDAP, this is a general weird TLS behavior. The solution to this problem is to disable enforced TLS (delete olcSecurity attribute) on the LDAP server, and re-enable ldap:/// (in contrast to ldaps:///) in the slapd defaults file, but restrict it to the loopback interface (ldap://127.0.0.1/). This way all traffic is still forced to use TLS (with cipher restrictions enforced by the olcTLSCipherSuite attribute), but local services are still able to access the LDAP server.

libpam-ldap unable to connect to LDAP server over SSL/TLS

1 Answers1