ldapdb smtpd.conf postfix sends unbind to ldap

Dennis Matotek dennis at utiba.com
Sat Jan 14 22:06:21 EST 2006 

Hi List,

I've read through the mail list archive and get similar but different 
problems to people using ldapdb, smtp auth via sasl.

I have confirmed using ldapsearch, ldapwhoami that ldap and digest-m5 
authentication is working properly.  courier-imap uses the same 
authentication to the same ldap server and experiences no problems.  I 
cannot get smtps to authenticate to the ldap server.  According to 
ethereal trace the smtps server makes a connection then sends unbind 
request.  Ldap logs the incoming connection but nothing else.  Is there 
a way of debugging what is happening that I can look at?  Someone a 
previous ldapdb problem in the list said to use smtptest supplied by 
cyrus-imap-utils.  Since I'm running courier-imap on the same server I 
didn't want to load it in case it caused more problems.  Is there 
something I am missing? I am not really a C programmer so messing with 
code is problematic.

Any help is greatly appreciated.

Regards,

Dennis

ldapwhoami -U xxxxx -X u:xxxx -Y DIGEST-MD5 -H ldap://ser3 -ZZ
dn:uid=xxxxxx,ou=utiba,ou=people,dc=xxxx
Result: Success (0)

ldapsearch -H ldap://ser3 -U xxxx -W  -X u:xxxx -Y DIGEST-MD5 -s base -b
uid=xxxxx,ou=xxxx,ou=people,dc=xxxx '(objectclass=*)' userPassword -ZZ
dn: uid=xxxxxx,ou=xxxx,ou=People,dc=xxxx
userPassword:: ########

/etc/postfix/sasl/smtpd.conf
pwcheck_method: auxprop (toggle on/off makes no difference)
auxprop_plugin: ldapdb
ldapdb_uri: ldap://192.168.0.3
ldapdb_id: xxxxx
ldapdb_pw: ******
#ldapdb_starttls: demand (toggle on/off makes no difference)
ldapdb_mech: digest-md5
log_level: 1 (this doesn't seem to do anything)

log mail/info: (where it pass off to sasl)
postfix/smtpd[6687]:  SASL authentication misc: DIGEST-MD5 server step 2
postfix/smtpd[6687]: > unknown[192.168.1.30]: 535 Error: authentication 
failed
postfix/smtpd[6687]: watchdog_pat: 0x8084be8
postfix/smtpd[6687]: smtp_get: EOF

log ldap.log (level 255)
Jan 15 14:00:20 ser3 slapd[29914]: daemon: activity on 1 descriptors
Jan 15 14:00:20 ser3 slapd[29914]: daemon: new connection on 30
Jan 15 14:00:20 ser3 slapd[29914]: daemon: added 30r
Jan 15 14:00:20 ser3 slapd[29914]: daemon: activity on:
Jan 15 14:00:20 ser3 slapd[29914]:
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=6 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=7 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=8 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=9 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: activity on 1 descriptors
Jan 15 14:00:20 ser3 slapd[29914]: daemon: activity on:
Jan 15 14:00:20 ser3 slapd[29914]:  30r
Jan 15 14:00:20 ser3 slapd[29914]:
Jan 15 14:00:20 ser3 slapd[29914]: daemon: read activity on 30
Jan 15 14:00:20 ser3 slapd[29914]: connection_get(30)
Jan 15 14:00:20 ser3 slapd[29914]: connection_get(30): got connid=66
Jan 15 14:00:20 ser3 slapd[29914]: connection_read(30): checking for 
input on id=66
Jan 15 14:00:20 ser3 slapd[29914]: ber_get_next on fd 30 failed errno=0 
(Success)
Jan 15 14:00:20 ser3 slapd[29914]: connection_read(30): input error=-2 
id=66, closing.
Jan 15 14:00:20 ser3 slapd[29914]: connection_closing: readying conn=66 
sd=30 for close
Jan 15 14:00:20 ser3 slapd[29914]: connection_close: deferring conn=66 sd=30
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=6 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=7 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=8 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=9 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: activity on 1 descriptors
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=6 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=7 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=8 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: daemon: select: listen=9 
active_threads=0 tvp=NULL
Jan 15 14:00:20 ser3 slapd[29914]: do_unbind
Jan 15 14:00:20 ser3 slapd[29914]: connection_resched: attempting 
closing conn=66 sd=30
Jan 15 14:00:20 ser3 slapd[29914]: connection_close: conn=66 sd=30
Jan 15 14:00:20 ser3 slapd[29914]: daemon: removing 30

ethereal log:
as attachment scan1.ethereal



-----------------
Utiba Pty Ltd 
This message has been scanned for viruses and
dangerous content by Utiba mail server and is 
believed to be clean.

-------------- next part --------------
No.     Time        Source                Destination           Protocol Info
    451 9.029311    192.168.1.1           192.168.0.3           TCP      1935 > ldap [SYN] Seq=0 Ack=0 Win=5840 Len=0 MSS=1460 TSV=253310147 TSER=0 WS=2

Frame 451 (74 bytes on wire, 74 bytes captured)
Ethernet II, Src: 192.168.1.1 (00:02:a5:dd:2a:8c), Dst: 192.168.1.254 (00:11:95:c7:12:b1)
Internet Protocol, Src: 192.168.1.1 (192.168.1.1), Dst: 192.168.0.3 (192.168.0.3)
Transmission Control Protocol, Src Port: 1935 (1935), Dst Port: ldap (389), Seq: 0, Ack: 0, Len: 0
    Source port: 1935 (1935)
    Destination port: ldap (389)
    Sequence number: 0    (relative sequence number)
    Header length: 40 bytes
    Flags: 0x0002 (SYN)
    Window size: 5840
    Checksum: 0xf2df [correct]
    Options: (20 bytes)

No.     Time        Source                Destination           Protocol Info
    452 9.030349    192.168.0.3           192.168.1.1           TCP      ldap > 1935 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3629615146 TSER=253310147 WS=2

Frame 452 (74 bytes on wire, 74 bytes captured)
Ethernet II, Src: 192.168.1.254 (00:11:95:c7:12:b1), Dst: 192.168.1.1 (00:02:a5:dd:2a:8c)
Internet Protocol, Src: 192.168.0.3 (192.168.0.3), Dst: 192.168.1.1 (192.168.1.1)
Transmission Control Protocol, Src Port: ldap (389), Dst Port: 1935 (1935), Seq: 0, Ack: 1, Len: 0
    Source port: ldap (389)
    Destination port: 1935 (1935)
    Sequence number: 0    (relative sequence number)
    Acknowledgement number: 1    (relative ack number)
    Header length: 40 bytes
    Flags: 0x0012 (SYN, ACK)
    Window size: 5792
    Checksum: 0xb895 [correct]
    Options: (20 bytes)
    SEQ/ACK analysis

No.     Time        Source                Destination           Protocol Info
    453 9.030465    192.168.1.1           192.168.0.3           TCP      1935 > ldap [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=253310149 TSER=3629615146

Frame 453 (66 bytes on wire, 66 bytes captured)
Ethernet II, Src: 192.168.1.1 (00:02:a5:dd:2a:8c), Dst: 192.168.1.254 (00:11:95:c7:12:b1)
Internet Protocol, Src: 192.168.1.1 (192.168.1.1), Dst: 192.168.0.3 (192.168.0.3)
Transmission Control Protocol, Src Port: 1935 (1935), Dst Port: ldap (389), Seq: 1, Ack: 1, Len: 0
    Source port: 1935 (1935)
    Destination port: ldap (389)
    Sequence number: 1    (relative sequence number)
    Acknowledgement number: 1    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0010 (ACK)
    Window size: 5840 (scaled)
    Checksum: 0xf846 [correct]
    Options: (12 bytes)
    SEQ/ACK analysis

No.     Time        Source                Destination           Protocol Info
    456 9.036467    192.168.1.1           192.168.0.3           LDAP     MsgId=1 Unbind Request

Frame 456 (73 bytes on wire, 73 bytes captured)
Ethernet II, Src: 192.168.1.1 (00:02:a5:dd:2a:8c), Dst: 192.168.1.254 (00:11:95:c7:12:b1)
Internet Protocol, Src: 192.168.1.1 (192.168.1.1), Dst: 192.168.0.3 (192.168.0.3)
Transmission Control Protocol, Src Port: 1935 (1935), Dst Port: ldap (389), Seq: 1, Ack: 1, Len: 7
    Source port: 1935 (1935)
    Destination port: ldap (389)
    Sequence number: 1    (relative sequence number)
    Next sequence number: 8    (relative sequence number)
    Acknowledgement number: 1    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0018 (PSH, ACK)
    Window size: 5840 (scaled)
    Checksum: 0xc4ea [correct]
    Options: (12 bytes)
Lightweight Directory Access Protocol
    LDAP Message, Unbind Request
        Message Id: 1
        Message Type: Unbind Request (0x02)
        Message Length: 0

No.     Time        Source                Destination           Protocol Info
    457 9.036638    192.168.1.1           192.168.0.3           TCP      1935 > ldap [FIN, ACK] Seq=8 Ack=1 Win=5840 Len=0 TSV=253310155 TSER=3629615146

Frame 457 (66 bytes on wire, 66 bytes captured)
Ethernet II, Src: 192.168.1.1 (00:02:a5:dd:2a:8c), Dst: 192.168.1.254 (00:11:95:c7:12:b1)
Internet Protocol, Src: 192.168.1.1 (192.168.1.1), Dst: 192.168.0.3 (192.168.0.3)
Transmission Control Protocol, Src Port: 1935 (1935), Dst Port: ldap (389), Seq: 8, Ack: 1, Len: 0
    Source port: 1935 (1935)
    Destination port: ldap (389)
    Sequence number: 8    (relative sequence number)
    Acknowledgement number: 1    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0011 (FIN, ACK)
    Window size: 5840 (scaled)
    Checksum: 0xf838 [correct]
    Options: (12 bytes)

No.     Time        Source                Destination           Protocol Info
    458 9.036701    192.168.0.3           192.168.1.1           TCP      ldap > 1935 [ACK] Seq=1 Ack=8 Win=5792 Len=0 TSV=3629615152 TSER=253310154

Frame 458 (66 bytes on wire, 66 bytes captured)
Ethernet II, Src: 192.168.1.254 (00:11:95:c7:12:b1), Dst: 192.168.1.1 (00:02:a5:dd:2a:8c)
Internet Protocol, Src: 192.168.0.3 (192.168.0.3), Dst: 192.168.1.1 (192.168.1.1)
Transmission Control Protocol, Src Port: ldap (389), Dst Port: 1935 (1935), Seq: 1, Ack: 8, Len: 0
    Source port: ldap (389)
    Destination port: 1935 (1935)
    Sequence number: 1    (relative sequence number)
    Acknowledgement number: 8    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0010 (ACK)
    Window size: 5792 (scaled)
    Checksum: 0xf840 [correct]
    Options: (12 bytes)
    SEQ/ACK analysis

No.     Time        Source                Destination           Protocol Info
    460 9.037539    192.168.0.3           192.168.1.1           TCP      ldap > 1935 [FIN, ACK] Seq=1 Ack=9 Win=5792 Len=0 TSV=3629615153 TSER=253310155

Frame 460 (66 bytes on wire, 66 bytes captured)
Ethernet II, Src: 192.168.1.254 (00:11:95:c7:12:b1), Dst: 192.168.1.1 (00:02:a5:dd:2a:8c)
Internet Protocol, Src: 192.168.0.3 (192.168.0.3), Dst: 192.168.1.1 (192.168.1.1)
Transmission Control Protocol, Src Port: ldap (389), Dst Port: 1935 (1935), Seq: 1, Ack: 9, Len: 0
    Source port: ldap (389)
    Destination port: 1935 (1935)
    Sequence number: 1    (relative sequence number)
    Acknowledgement number: 9    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0011 (FIN, ACK)
    Window size: 5792 (scaled)
    Checksum: 0xf83c [correct]
    Options: (12 bytes)
    SEQ/ACK analysis

No.     Time        Source                Destination           Protocol Info
    461 9.037602    192.168.1.1           192.168.0.3           TCP      1935 > ldap [ACK] Seq=9 Ack=2 Win=5840 Len=0 TSV=253310156 TSER=3629615153

Frame 461 (66 bytes on wire, 66 bytes captured)
Ethernet II, Src: 192.168.1.1 (00:02:a5:dd:2a:8c), Dst: 192.168.1.254 (00:11:95:c7:12:b1)
Internet Protocol, Src: 192.168.1.1 (192.168.1.1), Dst: 192.168.0.3 (192.168.0.3)
Transmission Control Protocol, Src Port: 1935 (1935), Dst Port: ldap (389), Seq: 9, Ack: 2, Len: 0
    Source port: 1935 (1935)
    Destination port: ldap (389)
    Sequence number: 9    (relative sequence number)
    Acknowledgement number: 2    (relative ack number)
    Header length: 32 bytes
    Flags: 0x0010 (ACK)
    Window size: 5840 (scaled)
    Checksum: 0xf82f [correct]
    Options: (12 bytes)
    SEQ/ACK analysis

More information about the Cyrus-sasl mailing list