Bug 1231228

Summary: automount via ldap with TLS/SSL support is not working
Product: Red Hat Enterprise Linux 7 Reporter: Patrik Kis <pkis>
Component: openldapAssignee: Matus Honek <mhonek>
Status: CLOSED ERRATA QA Contact: Patrik Kis <pkis>
Severity: high Docs Contact:
Priority: high    
Version: 7.2CC: ebenes, jsynacek, ksrot, mhonek, mkosek
Target Milestone: rcKeywords: Regression
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Cause: Patch for #1158005 added another destructor to already present one but did not include destructors' ordering. Consequence: Destructors got called in wrong order causing unloading prematurely. Fix: Underlying patch fixes the issue by adding destructors' ordering. Result: The issue is no more present.
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-11-19 08:53:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1373222    

Description Patrik Kis 2015-06-12 13:05:38 UTC
Description of problem:
The service automount stopped working with TLS/SSL after openldap was rebased to openldap-2.4.40-2.el7.
This is regression triggered by simple upgrade of openldap package.

Version-Release number of selected component (if applicable):
openldap-2.4.40-2.el7
autofs-5.0.7-48.el7

How reproducible:
always

Steps to Reproduce:
1. Configure openldap server with certificates:

# cat /etc/openldap/slapd.conf 
include         /etc/openldap/schema/core.schema
include         /etc/openldap/schema/cosine.schema
include         /etc/openldap/schema/inetorgperson.schema
include         /etc/openldap/schema/nis.schema
include         /etc/openldap/schema/autofs.schema
allow bind_v2
pidfile         /var/run/openldap/slapd.pid
argsfile        /var/run/openldap/slapd.args

database        bdb
suffix          dc=my-domain,dc=com
rootdn          "cn=Manager,dc=my-domain,dc=com"
# password is 'x'
rootpw          {SSHA}tOSmeQCcYIm1S9ujgpg2Km5rpUnR9dRB

directory       /var/lib/ldap/
TLSCipherSuite          HIGH:MEDIUM:+SSLv2:+SSLv3:RSA
TLSCertificateFile      /etc/openldap/cacerts/server.crt
TLSCertificateKeyFile   /etc/openldap/cacerts/server.key
TLSCACertificateFile    /etc/openldap/cacerts/ca.crt
TLSVerifyClient         allow
#
# ll /etc/openldap/cacerts/
total 12
-rw-------. 1 ldap ldap 1172 Jun 12 14:14 ca.crt
-rw-------. 1 ldap ldap 1042 Jun 12 14:14 server.crt
-rw-------. 1 ldap ldap 1679 Jun 12 14:14 server.key
#
# cp `rpm -ql autofs | grep autofs.schema` /etc/openldap/schema/


2. Populate the server with data:

# cat data.ldif
dn: dc=my-domain,dc=com
objectClass: dcObject
objectClass: organization
dc: my-domain
o: RedHatTestSystem Example
description: LDAP test organization

dn: cn=Manager,dc=my-domain,dc=com
objectClass: organizationalRole
cn: Manager
description: LDAP test manager

dn: uid=ldaptester,dc=my-domain,dc=com
objectClass: posixAccount
objectClass: organizationalPerson
objectClass: inetOrgPerson
uid: ldaptester
uidNumber: 100000
gidNumber: 100000
homeDirectory: /tmp
gecos: LDAP test user
loginShell: /bin/bash
userPassword: {SSHA}9p1SVd1SuctXU/TwNnfsxq3vT9W4fedG
objectClass: person
sn: ldaptester
givenName: ld
cn: LDAP test person
description: LDAP test user

dn: cn=ldapgroup,dc=my-domain,dc=com
objectClass: posixGroup
cn: ldapgroup
userPassword: x
gidNumber: 100000
memberUid: ldaptester
description: LDAP test group

# Setting up container for Users OU
dn: ou=People,dc=my-domain,dc=com
objectclass: top
objectclass: organizationalUnit
ou: People

# Setting up admin handle for People OU
dn: cn=admin,ou=People,dc=my-domain,dc=com
cn: admin
objectclass: top
objectclass: organizationalRole
objectclass: simpleSecurityObject
userPassword: x

dn: ou=auto.master,dc=my-domain,dc=com
objectClass: top
objectClass: automountMap
ou: auto.master

dn: ou=auto.testdir,dc=my-domain,dc=com
objectClass: top
objectClass: automountMap
ou: auto.testdir

dn: cn=/testdir,ou=auto.master,dc=my-domain,dc=com
objectClass: automount
automountInformation: ldap://my-domain.com:ou=auto.testdir,dc=my-domain,dc=com --timeout 60
cn: /testdir

dn: cn=loop,ou=auto.testdir,dc=my-domain,dc=com
objectClass: automount
automountInformation: -fstype=ext4 :/dev/loop0
cn: loop

3. Create a test mount server and dir

# mkdir /testdir
# dd if=/dev/zero of=/tmp/test count=10000 bs=1024
# losetup /dev/loop0 /tmp/test

4. Configure automount

# grep automount /etc/nsswitch.conf
automount: files ldap
#
# cat /etc/sysconfig/autofs
TIMEOUT=300
BROWSE_MODE="no"
SEARCH_BASE="dc=my-domain,dc=com"

LDAP_URI="ldap://my-domain.com"

MAP_OBJECT_CLASS="automountMap"
ENTRY_OBJECT_CLASS="automount"
MAP_ATTRIBUTE="automountMapName"
VALUE_ATTRIBUTE="automountInformation"

USE_MISC_DEVICE="yes"
OPTIONS=" -d -v "
#
# cat /etc/autofs_ldap_auth.conf
<?xml version="1.0" ?>
<autofs_ldap_sasl_conf
	usetls="no"
	tlsrequired="no"
/>


5. Test the mount with no TLS/SSL

# service autofs start
Redirecting to /bin/systemctl start  autofs.service
# ls /testdir/loop
lost+found
# mount |grep testdir
ldap:my-domain.com:ou=auto.testdir,dc=my-domain,dc=com on /testdir type autofs (rw,relatime,fd=19,pgrp=19187,timeout=60,minproto=5,maxproto=5,indirect)
/dev/loop0 on /testdir/loop type ext4 (rw,relatime,seclabel,data=ordered)
#

6. Test with TLS enabled

# sed -i 's/"no"/"yes"/' /etc/autofs_ldap_auth.conf
# cat /etc/autofs_ldap_auth.conf
<?xml version="1.0" ?>
<autofs_ldap_sasl_conf
	usetls="yes"
	tlsrequired="yes"
/>
# service autofs stop
Redirecting to /bin/systemctl stop  autofs.service
# mount |grep testdir
# service autofs start
Redirecting to /bin/systemctl start  autofs.service
# ls /testdir/loop
ls: cannot access /testdir/loop: No such file or directory
# mount |grep testdir
ldap:my-domain.com:ou=auto.testdir,dc=my-domain,dc=com on /testdir type autofs (rw,relatime,fd=19,pgrp=19252,timeout=60,minproto=5,maxproto=5,indirect)



The logs does not say too much:

 handle_packet: type = 3
 handle_packet_missing_indirect: token 47, name loop, request pid 19311
 attempting to mount entry /testdir/loop
 lookup_mount: lookup(ldap): looking up loop
 __init_ldap_connection: lookup(ldap): TLS required but START_TLS failed: Connect error
 lookup(ldap): lookup for loop failed: connection failed
 key "loop" not found in map source(s).
 dev_ioctl_send_fail: token = 47
 failed to mount /testdir/loop
 handle_packet: type = 3
 handle_packet_missing_indirect: token 48, name loop, request pid 19311
 dev_ioctl_send_fail: token = 48



slapd with debugging enabled:

>> when autofs is started:

557ad82a slap_listener_activate(8): 
557ad82a >>> slap_listener(ldap:///)
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 29 contents:
557ad82a op tag 0x77, time 1434114090
ber_get_next
557ad82a conn=1000 op=0 do_extended
ber_scanf fmt ({m) ber:
557ad82a send_ldap_extended: err=0 oid= len=0
557ad82a send_ldap_response: msgid=1 tag=120 err=0
ber_flush2: 14 bytes to sd 18
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
TLS: loaded CA certificate file /etc/openldap/cacerts/ca.crt.
TLS: error: the certificate '/etc/openldap/cacerts/server.crt' could not be found in the database - error -12285:Unable to find the certificate or key necessary for authentication..
TLS: certificate '/etc/openldap/cacerts/server.crt' successfully loaded from PEM file.
TLS: no unlocked certificate for certificate 'CN=my-domain.com,O=my-domain.com'.
TLS: certificate [CN=my-domain.com,O=my-domain.com] is valid
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
TLS certificate verification: subject: no certificate, issuer: no certificate, cipher: AES-128, security level: high, secret key bits: 128, total key bits: 128, cache hits: 0, cache misses: 1, cache not reusable: 0
557ad82a connection_read(18): unable to get TLS client DN, error=49 id=1000
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 12 contents:
557ad82a op tag 0x60, time 1434114090
ber_get_next
557ad82a conn=1000 op=1 do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt (m}) ber:
557ad82a >>> dnPrettyNormal: <>
557ad82a <<< dnPrettyNormal: <>, <>
557ad82a do_bind: version=3 dn="" method=128
557ad82a send_ldap_result: conn=1000 op=1 p=3
557ad82a send_ldap_response: msgid=2 tag=97 err=0
ber_flush2: 14 bytes to sd 18
557ad82a do_bind: v3 anonymous bind
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 107 contents:
557ad82a op tag 0x63, time 1434114090
ber_get_next
557ad82a conn=1000 op=2 do_search
ber_scanf fmt ({miiiib) ber:
557ad82a >>> dnPrettyNormal: <dc=my-domain,dc=com>
557ad82a <<< dnPrettyNormal: <dc=my-domain,dc=com>, <dc=my-domain,dc=com>
ber_scanf fmt ({mm}) ber:
ber_scanf fmt ({mm}) ber:
ber_scanf fmt ({M}}) ber:
557ad82a ==> limits_get: conn=1000 op=2 self="[anonymous]" this="dc=my-domain,dc=com"
557ad82a => bdb_search
557ad82a bdb_dn2entry("dc=my-domain,dc=com")
557ad82a => bdb_dn2id("dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x1
557ad82a entry_decode: "dc=my-domain,dc=com"
557ad82a <= entry_decode(dc=my-domain,dc=com)
557ad82a search_candidates: base="dc=my-domain,dc=com" (0x00000001) scope=2
557ad82a => bdb_dn2idl("dc=my-domain,dc=com")
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a => bdb_equality_candidates (nisMapName)
557ad82a <= bdb_equality_candidates: (nisMapName) not indexed
557ad82a bdb_search_candidates: id=-1 first=1 last=10
557ad82a bdb_search: 1 does not match filter
557ad82a entry_decode: "cn=Manager,dc=my-domain,dc=com"
557ad82a <= entry_decode(cn=Manager,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("cn=manager,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x2
557ad82a bdb_search: 2 does not match filter
557ad82a entry_decode: "uid=ldaptester,dc=my-domain,dc=com"
557ad82a <= entry_decode(uid=ldaptester,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("uid=ldaptester,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x3
557ad82a bdb_search: 3 does not match filter
557ad82a entry_decode: "cn=ldapgroup,dc=my-domain,dc=com"
557ad82a <= entry_decode(cn=ldapgroup,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("cn=ldapgroup,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x4
557ad82a bdb_search: 4 does not match filter
557ad82a entry_decode: "ou=People,dc=my-domain,dc=com"
557ad82a <= entry_decode(ou=People,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("ou=people,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x5
557ad82a bdb_search: 5 does not match filter
557ad82a entry_decode: "cn=admin,ou=People,dc=my-domain,dc=com"
557ad82a <= entry_decode(cn=admin,ou=People,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("cn=admin,ou=people,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x6
557ad82a bdb_search: 6 does not match filter
557ad82a entry_decode: "ou=auto.master,dc=my-domain,dc=com"
557ad82a <= entry_decode(ou=auto.master,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("ou=auto.master,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x7
557ad82a bdb_search: 7 does not match filter
557ad82a entry_decode: "ou=auto.testdir,dc=my-domain,dc=com"
557ad82a <= entry_decode(ou=auto.testdir,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("ou=auto.testdir,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x8
557ad82a bdb_search: 8 does not match filter
557ad82a entry_decode: "cn=/testdir,ou=auto.master,dc=my-domain,dc=com"
557ad82a <= entry_decode(cn=/testdir,ou=auto.master,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("cn=/testdir,ou=auto.master,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0x9
557ad82a bdb_search: 9 does not match filter
557ad82a entry_decode: "cn=loop,ou=auto.testdir,dc=my-domain,dc=com"
557ad82a <= entry_decode(cn=loop,ou=auto.testdir,dc=my-domain,dc=com)
557ad82a => bdb_dn2id("cn=loop,ou=auto.testdir,dc=my-domain,dc=com")
557ad82a <= bdb_dn2id: got id=0xa
557ad82a bdb_search: 10 does not match filter
557ad82a send_ldap_result: conn=1000 op=2 p=3
557ad82a send_ldap_response: msgid=3 tag=101 err=0
ber_flush2: 14 bytes to sd 18
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 97 contents:
557ad82a op tag 0x63, time 1434114090
ber_get_next
557ad82a conn=1000 op=3 do_search
ber_scanf fmt ({miiiib) ber:
557ad82a >>> dnPrettyNormal: <dc=my-domain,dc=com>
557ad82a <<< dnPrettyNormal: <dc=my-domain,dc=com>, <dc=my-domain,dc=com>
ber_scanf fmt ({mm}) ber:
ber_scanf fmt ({mm}) ber:
ber_scanf fmt ({M}}) ber:
557ad82a ==> limits_get: conn=1000 op=3 self="[anonymous]" this="dc=my-domain,dc=com"
557ad82a => bdb_search
557ad82a bdb_dn2entry("dc=my-domain,dc=com")
557ad82a search_candidates: base="dc=my-domain,dc=com" (0x00000001) scope=2
557ad82a => bdb_dn2idl("dc=my-domain,dc=com")
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a => bdb_equality_candidates (ou)
557ad82a <= bdb_equality_candidates: (ou) not indexed
557ad82a bdb_search_candidates: id=-1 first=1 last=10
557ad82a bdb_search: 1 does not match filter
557ad82a bdb_search: 2 does not match filter
557ad82a bdb_search: 3 does not match filter
557ad82a bdb_search: 4 does not match filter
557ad82a bdb_search: 5 does not match filter
557ad82a bdb_search: 6 does not match filter
557ad82a => send_search_entry: conn 1000 dn="ou=auto.master,dc=my-domain,dc=com"
ber_flush2: 66 bytes to sd 18
557ad82a <= send_search_entry: conn 1000 exit.
557ad82a bdb_search: 8 does not match filter
557ad82a bdb_search: 9 does not match filter
557ad82a bdb_search: 10 does not match filter
557ad82a send_ldap_result: conn=1000 op=3 p=3
557ad82a send_ldap_response: msgid=4 tag=101 err=0
ber_flush2: 14 bytes to sd 18
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 110 contents:
557ad82a op tag 0x63, time 1434114090
ber_get_next
557ad82a conn=1000 op=4 do_search
ber_scanf fmt ({miiiib) ber:
557ad82a >>> dnPrettyNormal: <ou=auto.master,dc=my-domain,dc=com>
557ad82a <<< dnPrettyNormal: <ou=auto.master,dc=my-domain,dc=com>, <ou=auto.master,dc=my-domain,dc=com>
ber_scanf fmt ({mm}) ber:
ber_scanf fmt ({M}}) ber:
557ad82a ==> limits_get: conn=1000 op=4 self="[anonymous]" this="ou=auto.master,dc=my-domain,dc=com"
557ad82a => bdb_search
557ad82a bdb_dn2entry("ou=auto.master,dc=my-domain,dc=com")
557ad82a search_candidates: base="ou=auto.master,dc=my-domain,dc=com" (0x00000007) scope=2
557ad82a => bdb_dn2idl("ou=auto.master,dc=my-domain,dc=com")
557ad82a <= bdb_dn2idl: id=2 first=7 last=9
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a => bdb_equality_candidates (objectClass)
557ad82a <= bdb_equality_candidates: (objectClass) not indexed
557ad82a bdb_search_candidates: id=2 first=7 last=9
557ad82a bdb_search: 7 does not match filter
557ad82a => send_search_entry: conn 1000 dn="cn=/testdir,ou=auto.master,dc=my-domain,dc=com"
ber_flush2: 174 bytes to sd 18
557ad82a <= send_search_entry: conn 1000 exit.
557ad82a send_ldap_result: conn=1000 op=4 p=3
557ad82a send_ldap_response: msgid=5 tag=101 err=0
ber_flush2: 14 bytes to sd 18
557ad82a connection_get(18): got connid=1000
557ad82a connection_read(18): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 5 contents:
557ad82a op tag 0x42, time 1434114090
ber_get_next
557ad82a ber_get_next on fd 18 failed errno=0 (Success)
557ad82a conn=1000 op=5 do_unbind
557ad82a connection_close: conn=1000 sd=18

>> when the test file is accessed:

557ad82e slap_listener_activate(8): 
557ad82e >>> slap_listener(ldap:///)
557ad82e connection_get(18): got connid=1001
557ad82e connection_read(18): checking for input on id=1001
ber_get_next
ber_get_next: tag 0x30 len 29 contents:
557ad82e op tag 0x77, time 1434114094
ber_get_next
557ad82e conn=1001 op=0 do_extended
ber_scanf fmt ({m) ber:
557ad82e send_ldap_extended: err=0 oid= len=0
557ad82e send_ldap_response: msgid=1 tag=120 err=0
ber_flush2: 14 bytes to sd 18
557ad82e connection_get(18): got connid=1001
557ad82e connection_read(18): checking for input on id=1001
TLS: error: accept - force handshake failure: errno 11 - moznss error -5938
TLS: can't accept: TLS error -5938:Encountered end of file.
557ad82e connection_read(18): TLS accept failure error=-1 id=1001, closing
557ad82e connection_close: conn=1001 sd=18

Comment 7 Matus Honek 2015-07-23 09:37:23 UTC
The commit below repairs this issue introduced by the patch for #1158005, where there was already __attribute__ ((destructor)) present in the upstream code and the destructor introduced by #1158005 was called before the original one, which caused closing the secure session prematurely. For correction I added a destructor ordering for both.

http://pkgs.devel.redhat.com/cgit/rpms/openldap/commit/?h=rhel-7.2&id=a0cc331d5f354b4aef0669977e164dce3b117463

Comment 11 errata-xmlrpc 2015-11-19 08:53:20 UTC
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.

https://rhn.redhat.com/errata/RHSA-2015-2131.html