Bug#470509: More debugging notes

[Chris Adams]

I've worked on a patch to add more informative syslog() use to pam_ldap, oriented towards system administrators who are investigating failures. With that and a number of hacked in syslog() calls in libldap2, it's starting to appear that the problem is caused by an underlying failure in gnutls_read(). Here's a transcript from the point where I've entered a password in /bin/su:

Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _open_session() successful

Mar 14 09:30:47 etch-dev su[17362]: ber_read_next() returning tag 48

Mar 14 09:30:47 etch-dev su[17362]: sb_tls_read() failed: returning -59



The attached patch applies against the stock libpam-ldap-180 source:

Mar 14 09:30:47 etch-dev su[17362]: (pam_unix) authentication failure; logname= uid=1000 euid=0 tty=pts/1 ruser=chris rhost= user=jb Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _open_session(): _set_ssl_default_options() successful Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _open_session(): ldap_initialize() successful Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _open_session(): calling ldap_set_option() for SSL Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _open_session(): calling ldap_set_option() for misc options Mar 14 09:30:47 etch-dev su[17362]: wait4msg: ldap_int_select() returned 1 Mar 14 09:30:47 etch-dev su[17362]: wait4msg: try_read1msg() in ugly loop returned 97 Mar 14 09:30:47 etch-dev su[17362]: wait4msg: ldap_int_select() returned 1 Mar 14 09:30:47 etch-dev su[17362]: ber_get_next() waiting for more data: res 16376 < to_go 44954: Resource temporarily unavailable Mar 14 09:30:47 etch-dev su[17362]: wait4msg: try_read1msg() in ugly loop returned -2 Mar 14 09:30:47 etch-dev su[17362]: wait4msg: ldap_int_select() returned 1 Mar 14 09:30:47 etch-dev su[17362]: SSL_read() failed: gnutls_read() returned -59: GnuTLS internal error. Mar 14 09:30:47 etch-dev su[17362]: ber_get_next() failed: ber_int_sb_read() returned -59 Mar 14 09:30:47 etch-dev su[17362]: try_read1msg() failed: LDAP_SERVER_DOWN caused by ber_get_next() returning LBER_DEFAULT: Success Mar 14 09:30:47 etch-dev su[17362]: wait4msg: try_read1msg() in ugly loop returned -1 Mar 14 09:30:47 etch-dev su[17362]: ldap_search_s() failed: ldap_result(base="ou=People,dc=snl,dc=salk,dc=edu", filter="(uid=jb)") failed: ld_errno = 81 Mar 14 09:30:47 etch-dev su[17362]: pam_ldap: _get_user_info() failed: ldap_search_s(base="ou=People,dc=snl,dc=salk,dc=edu", filter="(uid=jb)") failed: Can't contact LDAP server

pam_ldap_syslogging.diff.gz
Description: GNU Zip compressed data

Chris

smime.p7s
Description: S/MIME cryptographic signature