Bug 1039903

This was reproduced in IPA but the underlying issue is in either openldap or NSS.

The issue is that with openldap in RHEL 5.x which uses OpenSSL for crypto the user gets a reasonable error message that the CN doesn't match.

The same operation in RHEL 6 which uses NSS for crypto a very strange error is returned.

The IPA client is doing an LDAP search under the hood. I imagine that this is easily reproduced using the ldapsearch tool.

We can't tell whether NSS is returning this confusing error message and openldap is merely passing it along or if openldap is doing additional work which may be resulting in this message.

I cannot reproduce this.

# grep rhel6 /etc/hosts
192.168.122.200  rhel6.virtual.com rhel-6-virt

# hostname
rhel6.virtual.com

# ipa-client-install --server=rhel-6-virt --realm=VIRTUAL.COM --domain=virtual.com --principal=admin --password=secret --unattended
Traceback (most recent call last):
  File "/usr/sbin/ipa-client-install", line 2377, in <module>
    sys.exit(main())
  File "/usr/sbin/ipa-client-install", line 2363, in main
    rval = install(options, env, fstore, statestore)
  File "/usr/sbin/ipa-client-install", line 1724, in install
    ret = ds.search(domain=options.domain, servers=options.server, hostname=hostname, ca_cert_path=get_cert_path(options.ca_cert_file))
  File "/usr/lib/python2.6/site-packages/ipaclient/ipadiscovery.py", line 242, in search
    ldapret = self.ipacheckldap(server, self.realm, ca_cert_path=ca_cert_path)
  File "/usr/lib/python2.6/site-packages/ipaclient/ipadiscovery.py", line 339, in ipacheckldap
    basedn = get_ipa_basedn(lh)
  File "/usr/lib/python2.6/site-packages/ipapython/ipautil.py", line 817, in get_ipa_basedn
    contexts = entries[0][1]['namingcontexts']
KeyError: 'namingcontexts'

I don't have any rules in the firewall.

It looks like 192.168.122.200 is not FreeIPA and is for example AD (known issue, it has this symptom).

I just did a quick test against IPA in RHEL-6.5 and reproduction was very easy (vm-067.example.com is IPA server installed with ipa-server-install):

# wget http://vm-067.example.com/ipa/config/ca.crt -O /etc/ipa/ca.crt 

update /etc/hosts to add the alias

# ipa-client-install --server vm-067 --domain idm.lab.bos.redhat.com
LDAP Error: Connect error: TLS error -8157:Certificate extension not found.
LDAP Error: Connect error: TLS error -8157:Certificate extension not found.
Failed to verify that vm-067 is an IPA Server.
...

I tried to simulate the situation using ldapsearch and this is what I get:

....
TLS certificate verification: subject: CN=rhel6.virtual.com.BADDOMAIN,O=Red Hat,L=Brno,C=CZ, issuer: CN=ca.cert.org,OU=RH,O=Red Hat Testing CA,L=Brno,ST=Czech Republic,C=CZ, cipher: AES-256, security level: high, secret key bits: 256, total key bits: 256, cache hits: 0, cache misses: 0, cache not reusable: 0
TLS: hostname (rhel6.virtual.com) does not match common name in certificate (rhel6.virtual.com.BADDOMAIN).
TLS: can't connect: TLS error -8157:Certificate extension not found..
tls_write: want=37, written=37
....

Notice the third line, which is exactly what you are requesting. Please, verify that IPA is checking for the error string correctly.

# rpm -q openldap
openldap-2.4.23-34.el6_5.1.x86_64

Hmm, formatting really invalidated what "third line" was supposed to mean.

Notice this line in the output:

TLS: hostname (rhel6.virtual.com) does not match common name in certificate (rhel6.virtual.com.BADDOMAIN).

IPA isn't using ldapsearch to make the connection so this isn't exactly and apples to apples comparison.

A third possible culprit is python-ldap not returning the correct error. Note that the LAST error you show is the one we get, so maybe python-ldap only returns the last one that openldap provides.

Here is a cut-down snippet of what we do:

    SASL_GSSAPI = ldap.sasl.sasl({},'GSSAPI')

    conn = ldap.initialize(url)
    conn.set_option(ldap.OPT_X_SASL_NOCANON, ldap.OPT_ON)
    try:
        conn.sasl_interactive_bind_s('', SASL_GSSAPI)
        result = conn.search_st(str(dn), ldap.SCOPE_BASE, 'objectclass=pkiCA',
                                [ca_cert_attr], timeout=10)
    except ldap.NO_SUCH_OBJECT, e:
        root_logger.debug("get_ca_cert_from_ldap() error: %s",
                          convert_ldap_error(e))
        raise errors.NoCertificateError(entry=url)
    except ldap.SERVER_DOWN, e:
        root_logger.debug("get_ca_cert_from_ldap() error: %s",
                          convert_ldap_error(e))
        raise errors.NetworkError(uri=url, error=str(e))
    except Exception, e:
        root_logger.debug("get_ca_cert_from_ldap() error: %s",
                          convert_ldap_error(e))
        raise errors.LDAPError(str(e))

I debugged this a little bit more thouroughly...

Running the program under gdb:

LDAPTLS_CACERT=$(pwd)/cacert.pem LDAPTLS_REQCERT=demand gdb --args ldapsearch -d 1 -x -w secret -D "cn=Manager,rhel6.virtual.com" -H "ldaps://rhel6.virtual.com:22222" -b "cn=config" "olcBdbConfig"

After setting a breakpoint and running the program, here's my starting point:

(gdb) bt
#0  tlsm_session_chkhost (ld=0x616270, session=0x687fc0, name_in=0x61f400 "rhel6.virtual.com") at ../../../libraries/libldap/tls_m.c:2778
#1  0x00007ffff7bc2c66 in ldap_pvt_tls_check_hostname (ld=0x616270, s=<value optimized out>, name_in=<value optimized out>) at ../../../libraries/libldap/tls2.c:508
#2  0x00007ffff7bc3ef2 in ldap_int_tls_connect (ld=0x616270, conn=<value optimized out>, host=0x61f400 "rhel6.virtual.com") at ../../../libraries/libldap/tls2.c:373
#3  0x00007ffff7bc40f8 in ldap_int_tls_start (ld=0x616270, conn=<value optimized out>, srv=<value optimized out>) at ../../../libraries/libldap/tls2.c:845
#4  0x00007ffff7b9ec33 in ldap_int_open_connection (ld=0x616270, conn=0x616170, srv=0x61f380, async=<value optimized out>) at ../../../libraries/libldap/open.c:417
#5  0x00007ffff7bb22ef in ldap_new_connection (ld=0x616270, srvlist=0x616338, use_ldsb=1, connect=<value optimized out>, bind=0x0) at ../../../libraries/libldap/request.c:425
#6  0x00007ffff7b9e99d in ldap_open_defconn (ld=0x616270) at ../../../libraries/libldap/open.c:41
#7  0x00007ffff7bb3334 in ldap_send_initial_request (ld=0x616270, msgtype=96, dn=0x616050 "cn=Manager,rhel6.virtual.com", ber=0x6161f0, msgid=1) at ../../../libraries/libldap/request.c:106
#8  0x00007ffff7ba8b3e in ldap_sasl_bind (ld=0x616270, dn=0x616050 "cn=Manager,rhel6.virtual.com", mechanism=0x0, cred=0x6156b0, sctrls=0x0, cctrls=<value optimized out>, msgidp=0x7fffffffa04c) at ../../../libraries/libldap/sasl.c:148
#9  0x000000000040992d in tool_bind (ld=0x616270) at ../../../clients/tools/common.c:1439
#10 0x0000000000406a03 in main (argc=<value optimized out>, argv=<value optimized out>) at ../../../clients/tools/ldapsearch.c:902

After couple of steps, later in the same function:

...
(gdb) n
2929                            Debug( LDAP_DEBUG_ANY, "TLS: hostname (%s) does not match "
(gdb) n
TLS: hostname (rhel6.virtual.com) does not match common name in certificate (rhel6.virtual.com.BADDOMAIN).

First observation is that what I considered an error is actually an internal debug statement.

Let's go on:

(gdb) finish
Run till exit from #0  tlsm_session_chkhost (ld=0x616270, session=<value optimized out>, name_in=<value optimized out>) at ../../../libraries/libldap/tls_m.c:2933
0x00007ffff7bc2c66 in ldap_pvt_tls_check_hostname (ld=0x616270, s=<value optimized out>, name_in=<value optimized out>) at ../../../libraries/libldap/tls2.c:508
508                     ld->ld_errno = tls_imp->ti_session_chkhost( ld, session, name_in );
Value returned is $1 = -11

(gdb) p ld->ld_error 
$2 = 0x6a9280 "TLS: hostname does not match CN in peer certificate"

So, as can be seen, tlsm_session_chkhost() returns this mysterious -11, but sets the error correctly.

Going on:

(gdb) n
515     }
(gdb) n
ldap_int_tls_connect (ld=0x616270, conn=<value optimized out>, host=0x61f400 "rhel6.virtual.com") at ../../../libraries/libldap/tls2.c:376
376             if ( err < 0 )
(gdb) n
379                     if ( update_flags( sb, ssl, err )) {
(gdb) n
383                     msg = tls_imp->ti_session_errmsg( ssl, err, buf, sizeof(buf) );
(gdb) s
tlsm_session_errmsg (sess=0x687fc0, rc=-11, buf=0x7fffffff9c40  <incomplete sequence \310>, len=256) at ../../../libraries/libldap/tls_m.c:2721

If there was an error (which in our case there was), a new error message is assigned to 'msg'. The function pointer used here is actuall tlsm_session_errmsg(): 

...
(gdb) bt 
#0  tlsm_session_errmsg (sess=<value optimized out>, rc=<value optimized out>, buf=0x7fffffff9c40 "TLS error -8157:Certificate extension not found.", len=256) at ../../../libraries/libldap/tls_m.c:2738
#1  0x00007ffff7bc4001 in ldap_int_tls_connect (ld=0x616270, conn=<value optimized out>, host=0x61f400 "rhel6.virtual.com") at ../../../libraries/libldap/tls2.c:383
#2  0x00007ffff7bc40f8 in ldap_int_tls_start (ld=0x616270, conn=<value optimized out>, srv=<value optimized out>) at ../../../libraries/libldap/tls2.c:845
#3  0x00007ffff7b9ec33 in ldap_int_open_connection (ld=0x616270, conn=0x616170, srv=0x61f380, async=<value optimized out>) at ../../../libraries/libldap/open.c:417
#4  0x00007ffff7bb22ef in ldap_new_connection (ld=0x616270, srvlist=0x616338, use_ldsb=1, connect=<value optimized out>, bind=0x0) at ../../../libraries/libldap/request.c:425
#5  0x00007ffff7b9e99d in ldap_open_defconn (ld=0x616270) at ../../../libraries/libldap/open.c:41
#6  0x00007ffff7bb3334 in ldap_send_initial_request (ld=0x616270, msgtype=96, dn=0x616050 "cn=Manager,rhel6.virtual.com", ber=0x6161f0, msgid=1) at ../../../libraries/libldap/request.c:106
#7  0x00007ffff7ba8b3e in ldap_sasl_bind (ld=0x616270, dn=0x616050 "cn=Manager,rhel6.virtual.com", mechanism=0x0, cred=0x6156b0, sctrls=0x0, cctrls=<value optimized out>, msgidp=0x7fffffffa04c) at ../../../libraries/libldap/sasl.c:148
#8  0x000000000040992d in tool_bind (ld=0x616270) at ../../../clients/tools/common.c:1439
#9  0x0000000000406a03 in main (argc=<value optimized out>, argv=<value optimized out>) at ../../../clients/tools/ldapsearch.c:902

The function looks like this:

static char *
tlsm_session_errmsg( tls_session *sess, int rc, char *buf, size_t len )
{
	int i;
	int prerror = PR_GetError();

	i = PR_GetErrorTextLength();
	if ( i > len ) {
		char *msg = LDAP_MALLOC( i+1 );
		PR_GetErrorText( msg );
		memcpy( buf, msg, len );
		LDAP_FREE( msg );
	} else if ( i ) {
		PR_GetErrorText( buf );
	} else if ( prerror ) {
		i = PR_snprintf( buf, len, "TLS error %d:%s",
						 prerror, PR_ErrorToString( prerror, PR_LANGUAGE_I_DEFAULT ) );
	}

	return ( i > 0 ) ? buf : NULL;
}

Letting the function finish results in:

(gdb) finish
Run till exit from #0  tlsm_session_errmsg (sess=0x687fc0, rc=-11, buf=0x7fffffff9c40  <incomplete sequence \310>, len=256) at ../../../libraries/libldap/tls_m.c:2721
ldap_int_tls_connect (ld=0x616270, conn=<value optimized out>, host=0x61f400 "rhel6.virtual.com") at ../../../libraries/libldap/tls2.c:384
384                     if ( msg ) {
Value returned is $6 = 0x7fffffff9c40 "TLS error -8157:Certificate extension not found."

Which then gets propagated further:

(gdb) n
385                             if ( ld->ld_error ) {
(gdb) n
386                                     LDAP_FREE( ld->ld_error );
(gdb) 
388                             ld->ld_error = LDAP_STRDUP( msg );

Second observation is that the PR_* calls actually return wrong error string, which gets further propagated into the ldap library and then to the caller.

Third observation is that the entire problem could possible be worked around by calling tlsm_session_chkhost() first.

Created attachment 895394 [details]
Reproducer

The PR_* function leads to nspr, which probably has something to do with NSS.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2014-1426.html