debug Pass-Trough authentication with SASL

[Dan White]

On 02/08/16 14:28 +0100, Thomas Peter via Cyrus-sasl wrote:
>Hi,
>
>I run
>saslauthd 2.1.26
>authentication mechanisms: getpwent kerberos5 rimap shadow ldap
>
>and in my etc/saslauthd.conf I do have
>ldap_servers: ldap://example.com:389
>which is a round-robin dns (10 IPs behind)
>
>Now I have the problem that sometimes the connection to example.com 
>seems to hang:
>
>Jan 18 17:06:15 uit-algo-p-11 slapd[130335]: conn=1410 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" method=128
>Jan 18 17:06:15 uit-algo-p-11 slapd[130335]: conn=1410 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" mech=SIMPLE ssf=0
>Jan 18 17:06:15 uit-algo-p-11 slapd[130335]: conn=1410 op=0 RESULT 
>tag=97 err=0 text=
>Jan 18 17:06:15 uit-algo-p-11 slapd[130335]: conn=1411 fd=15 ACCEPT 
>from IP=127.0.0.1:54144 (IP=127.0.0.1:9389)
>Jan 18 17:06:15 uit-algo-p-11 slapd[130335]: conn=1411 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" method=128
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1410 op=1 UNBIND
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1410 fd=14 closed
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: connection_read(14): no 
>connection!
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1408 op=2 UNBIND
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1408 fd=13 closed
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: connection_read(13): no 
>connection!
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1407 op=1 UNBIND
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: conn=1407 fd=10 closed
>Jan 18 17:06:16 uit-algo-p-11 slapd[130335]: connection_read(10): no 
>connection!
>Jan 18 17:21:49 uit-algo-p-11 saslauthd[131005]: ldap_simple_bind() 
>failed -1 (Can't contact LDAP server).
>Jan 18 17:21:49 uit-algo-p-11 saslauthd[131005]: Retrying authentication
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1411 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" mech=SIMPLE ssf=0
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1411 op=0 RESULT 
>tag=97 err=0 text=
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1411 op=1 SRCH 
>base="dc=example,dc=com" scope=1 deref=3 filter="(&(uid=petert))"
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: <= 
>mdb_equality_candidates: (uid) not indexed
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1411 op=1 SEARCH 
>RESULT tag=101 err=0 nentries=1 text=
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1412 fd=10 ACCEPT 
>from IP=127.0.0.1:54761 (IP=127.0.0.1:9389)
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1412 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" method=128
>Jan 18 17:21:49 uit-algo-p-11 saslauthd[131009]: ldap_simple_bind() 
>failed -1 (Can't contact LDAP server).
>Jan 18 17:21:49 uit-algo-p-11 saslauthd[131009]: Retrying authentication
>Jan 18 17:21:49 uit-algo-p-11 slapd[130335]: conn=1412 op=0 BIND 
>dn="cn=petert,dc=example,dc=com" mech=SIMPLE ssf=0
>
>The message "ldap_simple_bind() failed -1 (Can't contact LDAP 
>server)." is quite common and it looks like I get it every bind.
>What I'm now looking for is some help in diagnosis like "to which IP 
>is saslauthd now connecting to and trying the bind"
>
>Any hints?
>btw: I can't run my openldap and saslauthd as root hence the 
>portnumbers > 1024.

You can enable debugging output by running saslauthd in debug mode (-d),
and by specifying a debug level for the libldap library with 'ldap_debug'
within your saslauthd.conf. That's an undocumented option for the saslauthd
ldap backend, but is used to set the LDAP_OPT_DEBUG_LEVEL. See
ldap_set_option(3), and consult include/ldap_log.h for valid values
(LDAP_DEBUG_*).

Also, check your ldap.conf (see ldap.conf(5)) as the ldap backend will use
any defaults you've configured there.

Try reproducing the trouble with ldapsearch/ldapwhoami on the server
running saslauthd, which may ease trouble shooting.

-- 
Dan White