Re: Config scripts

[Marcus Merighi <mcmer@tor.at>]

Joe Bardgett schrieb:
> Max,
> 	Greetings and thank you for the link.  I agree that the ldap config
> is not really an issue but the SSL stuff is giving me a headache.  I cannot
> get my client to talk to the server through SSL/TLS.  Did you just follow
> the instructions on the web site and everything worked for you?  

Wasn't like a first try success :-) but after all it was mistakes I made
and the instructions were pretty perfect. But! I'n not using any
OpenLDAP command line tool to query. Only tried it with Mozilla address
book, which asked whether I wanted to accept the CA Certificate
{permanent|session|nope} and after 'permanent' everything worked. But

TLS_CACERT      /opt/LocalCA/cacert.pem

in the doc should do the same, I /guess/.

What
> version of openssl and openldap are you using?  

OpenSSL 0.9.7-beta3 30 Jul 2002
OpenBSD 3.2
Package openldap-server-2.0.27

I don't think
-Z[Z]  Issue  StartTLS (Transport Layer Security) extended
operation. If you use -ZZ, the command will require
the operation to be successful.

Is what you want. AFAIK that's supposed to force a TLS over usual
unsecured port. And my logs support that 'theory'.

$ ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W -H "ldap://127.0.0.1";
May 22 23:29:44 axe slapd[27660]: daemon: conn=28 fd=10 connection from
IP=127.0.0.1:2405 (IP=0.0.0.0:389) accepted.
May 22 23:29:44 axe slapd[27660]: conn=28 op=0 BIND
dn="CN=ADMIN,DC=TOR,DC=AT" method=128
May 22 23:29:44 axe slapd[27660]: conn=28 op=0 RESULT tag=97 err=0 text=
May 22 23:29:44 axe slapd[27660]: conn=28 op=1 SRCH base="dc=tor, dc=at"
scope=2 filter="(objectClass=*)"
May 22 23:29:44 axe slapd[27660]: conn=28 op=1 SEARCH RESULT tag=101
err=0 text=
May 22 23:29:44 axe slapd[27660]: conn=28 op=2 UNBIND
May 22 23:29:44 axe slapd[27660]: conn=-1 fd=10 closed
=> success
==========================
$ ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W -H "ldaps://127.0.0.1"
Enter LDAP Password:
Memory fault (core dumped)
May 22 23:30:18 axe slapd[27660]: daemon: conn=29 fd=10 connection from
IP=127.0.0.1:37936 (IP=0.0.0.0:636) accepted.
May 22 23:30:18 axe slapd[27660]: conn=-1 fd=10 closed
=> Failure
========================
$ ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W -ZZ
Memory fault (core dumped)
May 22 23:35:57 axe slapd[27660]: daemon: conn=35 fd=10 connection from
IP=127.0.0.1:27347 (IP=0.0.0.0:389) accepted.
May 22 23:35:57 axe slapd[27660]: conn=-1 fd=10 closed
=======================
now setting
loglevel -1
$sudo ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W \
	-H ldaps://ldap.tor.at -v -b '' -s base '(objectClass=*)' \
	namingContexts
$tail -f /var/log/ldap | grep err
May 22 23:48:24 axe slapd[27880]: connection_read(10): input error=-2
id=2, closing.
May 22 23:48:49 axe slapd[27880]: ber_get_next on fd 10 failed errno=0
(Undefined error: 0)
May 22 23:48:49 axe slapd[27880]: connection_read(10): input error=-2
id=3, closing.
===========================
Hmmmm, need more detail...
$ tail -f -n 0 /var/log/ldap > ldap.389
$ sudo ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W \
	-H ldap://ldap.tor.at -v -b '' -s base \
	'(objectClass=*)' namingContexts
$ tail -f -n 0 /var/log/ldap > ldap.636
$ sudo ldapsearch -D 'cn=Admin,dc=tor,dc=at' -x -W -H \
	ldaps://ldap.tor.at -v -b '' -s base '(objectClass=*)' \
	namingContexts
$ diff ldap.389 ldap.636
1,99c1,37
< May 22 23:55:25 axe slapd[27880]: daemon: activity on 1 descriptors
< May 22 23:55:25 axe slapd[27880]: daemon: new connection on 10
< May 22 23:55:25 axe slapd[27880]: daemon: conn=9 fd=10 connection from
IP=192.168.3.2:7508 (IP=0.0.0.0:389) accepted.
< May 22 23:55:25 axe slapd[27880]: daemon: added 10r
< May 22 23:55:25 axe slapd[27880]: daemon: activity on:
< May 22 23:55:25 axe slapd[27880]:
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=8
active_threads=0 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=9
active_threads=0 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: activity on 1 descriptors
< May 22 23:55:25 axe slapd[27880]: daemon: activity on:
< May 22 23:55:25 axe slapd[27880]:  10r
< May 22 23:55:25 axe slapd[27880]:
< May 22 23:55:25 axe slapd[27880]: daemon: read activity on 10
< May 22 23:55:25 axe slapd[27880]: connection_get(10)
< May 22 23:55:25 axe slapd[27880]: connection_get(10): got connid=9
< May 22 23:55:25 axe slapd[27880]: connection_read(10): checking for
input on id=9
< May 22 23:55:25 axe slapd[27880]: ber_get_next on fd 10 failed
errno=35 (Resource temporarily unavailable)
< May 22 23:55:25 axe slapd[27880]: do_bind
< May 22 23:55:25 axe slapd[27880]: do_bind: version=3
dn="cn=Admin,dc=tor,dc=at" method=128
< May 22 23:55:25 axe slapd[27880]: conn=9 op=0 BIND
dn="CN=ADMIN,DC=TOR,DC=AT" method=128
< May 22 23:55:25 axe slapd[27880]: ==> ldbm_back_bind: dn:
cn=Admin,dc=tor,dc=at
< May 22 23:55:25 axe slapd[27880]: dn2entry_r: dn: "CN=ADMIN,DC=TOR,DC=AT"
< May 22 23:55:25 axe slapd[27880]: => dn2id( "CN=ADMIN,DC=TOR,DC=AT" )
< May 22 23:55:25 axe slapd[27880]: ====>
cache_find_entry_dn2id("CN=ADMIN,DC=TOR,DC=AT"): 2 (1 tries)
< May 22 23:55:25 axe slapd[27880]: <= dn2id 2 (in cache)
< May 22 23:55:25 axe slapd[27880]: => id2entry_r( 2 )
< May 22 23:55:25 axe slapd[27880]: ====> cache_find_entry_id( 2 )
"cn=Admin,dc=tor,dc=at" (found) (1 tries)
< May 22 23:55:25 axe slapd[27880]: <= id2entry_r( 2 ) 0xa98a0 (cache)
< May 22 23:55:25 axe slapd[27880]: ====> cache_return_entry_r( 2 ):
returned (0)
< May 22 23:55:25 axe slapd[27880]: do_bind: v3 bind:
"cn=Admin,dc=tor,dc=at" to "cn=Admin,dc=tor,dc=at"
< May 22 23:55:25 axe slapd[27880]: send_ldap_result: conn=9 op=0 p=3
< May 22 23:55:25 axe slapd[27880]: send_ldap_result: 0::
< May 22 23:55:25 axe slapd[27880]: send_ldap_response: msgid=1 tag=97
err=0
< May 22 23:55:25 axe slapd[27880]: conn=9 op=0 RESULT tag=97 err=0 text=
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=8
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=9
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: activity on 1 descriptors
< May 22 23:55:25 axe slapd[27880]: daemon: activity on:
< May 22 23:55:25 axe slapd[27880]:  10r
< May 22 23:55:25 axe slapd[27880]:
< May 22 23:55:25 axe slapd[27880]: daemon: read activity on 10
< May 22 23:55:25 axe slapd[27880]: connection_get(10)
< May 22 23:55:25 axe slapd[27880]: connection_get(10): got connid=9
< May 22 23:55:25 axe slapd[27880]: connection_read(10): checking for
input on id=9
< May 22 23:55:25 axe slapd[27880]: ber_get_next on fd 10 failed
errno=35 (Resource temporarily unavailable)
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=8
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=9
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: do_search
< May 22 23:55:25 axe slapd[27880]: SRCH "" 0 0
< May 22 23:55:25 axe slapd[27880]:     0 0 0
< May 22 23:55:25 axe slapd[27880]: begin get_filter
< May 22 23:55:25 axe slapd[27880]: PRESENT
< May 22 23:55:25 axe slapd[27880]: end get_filter 0
< May 22 23:55:25 axe slapd[27880]:     filter: (objectClass=*)
< May 22 23:55:25 axe slapd[27880]:     attrs:
< May 22 23:55:25 axe slapd[27880]:  namingContexts
< May 22 23:55:25 axe slapd[27880]:
< May 22 23:55:25 axe slapd[27880]: conn=9 op=1 SRCH base="" scope=0
filter="(objectClass=*)"
< May 22 23:55:25 axe slapd[27880]: => test_filter
< May 22 23:55:25 axe slapd[27880]:     PRESENT
< May 22 23:55:25 axe slapd[27880]: => access_allowed: search access to
"" "objectClass" requested
< May 22 23:55:25 axe slapd[27880]: <= root access granted
< May 22 23:55:25 axe slapd[27880]: <= test_filter 6
< May 22 23:55:25 axe slapd[27880]: => send_search_entry: ""
< May 22 23:55:25 axe slapd[27880]: => access_allowed: read access to ""
"entry" requested
< May 22 23:55:25 axe slapd[27880]: <= root access granted
< May 22 23:55:25 axe slapd[27880]: => access_allowed: read access to ""
"namingContexts" requested
< May 22 23:55:25 axe slapd[27880]: <= root access granted
< May 22 23:55:25 axe slapd[27880]: => access_allowed: read access to ""
"namingContexts" requested
< May 22 23:55:25 axe slapd[27880]: <= root access granted
< May 22 23:55:25 axe slapd[27880]: conn=9 op=1 ENTRY dn=""
< May 22 23:55:25 axe slapd[27880]: <= send_search_entry
< May 22 23:55:25 axe slapd[27880]: send_ldap_result: conn=9 op=1 p=3
< May 22 23:55:25 axe slapd[27880]: send_ldap_result: 0::
< May 22 23:55:25 axe slapd[27880]: send_ldap_response: msgid=2 tag=101
err=0
< May 22 23:55:25 axe slapd[27880]: conn=9 op=1 RESULT tag=101 err=0 text=
< May 22 23:55:25 axe slapd[27880]: daemon: activity on 1 descriptors
< May 22 23:55:25 axe slapd[27880]: daemon: activity on:
< May 22 23:55:25 axe slapd[27880]:  10r
< May 22 23:55:25 axe slapd[27880]:
< May 22 23:55:25 axe slapd[27880]: daemon: read activity on 10
< May 22 23:55:25 axe slapd[27880]: connection_get(10)
< May 22 23:55:25 axe slapd[27880]: connection_get(10): got connid=9
< May 22 23:55:25 axe slapd[27880]: connection_read(10): checking for
input on id=9
< May 22 23:55:25 axe slapd[27880]: ber_get_next on fd 10 failed errno=0
(Undefined error: 0)
< May 22 23:55:25 axe slapd[27880]: connection_read(10): input error=-2
id=9, closing.
< May 22 23:55:25 axe slapd[27880]: connection_closing: readying conn=9
sd=10 for close
< May 22 23:55:25 axe slapd[27880]: connection_close: deferring conn=9
sd=10
< May 22 23:55:25 axe slapd[27880]: do_unbind
< May 22 23:55:25 axe slapd[27880]: conn=9 op=2 UNBIND
< May 22 23:55:25 axe slapd[27880]: connection_resched: attempting
closing conn=9 sd=10
< May 22 23:55:25 axe slapd[27880]: connection_close: conn=9 sd=10
< May 22 23:55:25 axe slapd[27880]: daemon: removing 10
< May 22 23:55:25 axe slapd[27880]: conn=-1 fd=10 closed
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=8
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=9
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: activity on 1 descriptors
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=8
active_threads=1 tvp=NULL
< May 22 23:55:25 axe slapd[27880]: daemon: select: listen=9
active_threads=1 tvp=NULL
---
> May 22 23:55:45 axe slapd[27880]: daemon: activity on 1 descriptors
> May 22 23:55:45 axe slapd[27880]: daemon: new connection on 10
> May 22 23:55:45 axe slapd[27880]: daemon: conn=10 fd=10 connection
from IP=192.168.3.2:21133 (IP=0.0.0.0:636) accepted.
> May 22 23:55:45 axe slapd[27880]: daemon: added 10r
> May 22 23:55:45 axe slapd[27880]: daemon: activity on:
> May 22 23:55:45 axe slapd[27880]:
> May 22 23:55:45 axe slapd[27880]: daemon: select: listen=8
active_threads=0 tvp=NULL
> May 22 23:55:45 axe slapd[27880]: daemon: select: listen=9
active_threads=0 tvp=NULL
> May 22 23:55:45 axe slapd[27880]: daemon: activity on 1 descriptors
> May 22 23:55:45 axe slapd[27880]: daemon: activity on:
> May 22 23:55:45 axe slapd[27880]:  10r
> May 22 23:55:45 axe slapd[27880]:
> May 22 23:55:45 axe slapd[27880]: daemon: read activity on 10
> May 22 23:55:45 axe slapd[27880]: connection_get(10)
> May 22 23:55:45 axe slapd[27880]: connection_get(10): got connid=10
> May 22 23:55:45 axe slapd[27880]: connection_read(10): checking for
input on id=10
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=8
active_threads=0 tvp=NULL
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=9
active_threads=0 tvp=NULL
> May 22 23:55:46 axe slapd[27880]: daemon: activity on 1 descriptors
> May 22 23:55:46 axe slapd[27880]: daemon: activity on:
> May 22 23:55:46 axe slapd[27880]:  10r
> May 22 23:55:46 axe slapd[27880]:
> May 22 23:55:46 axe slapd[27880]: daemon: read activity on 10
> May 22 23:55:46 axe slapd[27880]: connection_get(10)
> May 22 23:55:46 axe slapd[27880]: connection_get(10): got connid=10
> May 22 23:55:46 axe slapd[27880]: connection_read(10): checking for
input on id=10
> May 22 23:55:46 axe slapd[27880]: ber_get_next on fd 10 failed errno=0
(Undefined error: 0)
> May 22 23:55:46 axe slapd[27880]: connection_read(10): input error=-2
id=10, closing.
> May 22 23:55:46 axe slapd[27880]: connection_closing: readying conn=10
sd=10 for close
> May 22 23:55:46 axe slapd[27880]: connection_close: conn=10 sd=10
> May 22 23:55:46 axe slapd[27880]: daemon: removing 10
> May 22 23:55:46 axe slapd[27880]: conn=-1 fd=10 closed
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=8
active_threads=0 tvp=NULL
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=9
active_threads=0 tvp=NULL
> May 22 23:55:46 axe slapd[27880]: daemon: activity on 1 descriptors
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=8
active_threads=0 tvp=NULL
> May 22 23:55:46 axe slapd[27880]: daemon: select: listen=9
active_threads=0 tvp=NULL

=> that didn't help me to much, either.

============================


I just don't know where the
> communication failure is happening for me since I can get a response from
> the server when I do ldapsearch -Z but not with ldapsearch -ZZ.  Any help is
> appreciated.

Well, after all I don't know it either!

> 
> Thanks for your time,
> Joe B.

Got to go to bed, no more testing.

Pfirti, Max