#47684 "Encountered end of file." from OS X 10.8 client with SSL enabled
Closed: wontfix None Opened 10 years ago by iicodecll.

I recently setup 389-ds (1.2.11.15, @EPEL) on two RHEL6 machines with replication between two masters. We have a number of RHEL (5/6), FEDORA (19), and a bunch of OS X Snow Leopard, Lion, and Mountain Lion workstations. The RHEL and FEDORA workstations worked right out of the box after defining the TLS_CACERTDIR location in ldap.conf. Both SSL and START_TLS over 389 worked correctly. I haven't seen any problems with authentication, autofs, netgroups, hosts, or cups printers (save Fedora 19 which cups 1.6).

The OS X Mountain Lion machines we maintain are a different story. The machines will correctly establish a connection over 636 with SSL enabled for about 2 minutes (or less) when the connection appears to be dropped. The access log from one of the 389-ds nodes displays "closed - Encountered end of file." Any further communication times out between the 389-ds server and the Mountain Lion workstations appear to be non-existent. The communication fails for approximately 2 to 3 minutes until the Mountain Lion workstation establishes another connection. The issue repeats itself every couple of minutes.

The issue does not occur over the non-secure port. As far as I can tell, the LDAP client configuration (Directory Services/Open Directory) on Mountain Lion does not support START_TLS over the non-secure port. The issue also does not occur when authenticating against an Leopard Server with SSL enabled.

ldapsearch utilizing SSL and START_TLS appears to work just fine. I've tried the version provided by Apple, and another version compiled using MacPorts. Both have an identical ldap.conf calling TLS_CACERTDIR. I noticed with the Apple version of ldapsearch, I needed to insert the CA certificate directly into the "System" keychain before it would successfully search with SSL or START_TLS.

I haven't tried the same configuration on the Lion or Snow Leopard machines just yet. I will (hopefully) get to that later today.

I'm not sure if this is a client or server configuration issue on my behalf.

389-ds access log:

{{{[24/Jan/2014:13:22:19 -0500] conn=52 op=112 UNBIND
[24/Jan/2014:13:22:19 -0500] conn=52 op=112 fd=69 closed - U1
[24/Jan/2014:13:22:39 -0500] conn=53 fd=65 slot=65 SSL connection from 131.142.xxx.xxx to 131.142.yyy.yyy
[24/Jan/2014:13:22:39 -0500] conn=54 fd=69 slot=69 SSL connection from 131.142.xxx.xxx to 131.142.yyy.yyy
[24/Jan/2014:13:22:39 -0500] conn=53 op=-1 fd=65 closed - Encountered end of file.

[... 2 minutes later ...]
[24/Jan/2014:13:24:10 -0500] conn=54 SSL 256-bit AES
[24/Jan/2014:13:24:10 -0500] conn=54 op=1 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedSASLMechanisms defaultnamingcontext namingContexts schemanamingcontext"
[24/Jan/2014:13:24:10 -0500] conn=Internal op=-1 SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[24/Jan/2014:13:24:10 -0500] conn=Internal op=-1 RESULT err=0 tag=48 nentries=0 etime=0
[24/Jan/2014:13:24:10 -0500] conn=Internal op=-1 SRCH base="cn=config,cn=NetscapeRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[24/Jan/2014:13:24:10 -0500] conn=Internal op=-1 RESULT err=0 tag=48 nentries=0 etime=0
[24/Jan/2014:13:24:10 -0500] conn=54 op=1 ENTRY dn=""
[24/Jan/2014:13:24:10 -0500] conn=54 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[24/Jan/2014:13:24:10 -0500] conn=54 op=2 SRCH base="automountMapName=auto.sdo,ou=Maps,dc=example,dc=com" scope=2 filter="(&(|(objectClass=automount))(automountKey=\2a))" attrs="automountKey automountInformation objectClass"

389-ds error log:

{{{[24/Jan/2014:13:22:19 -0500] - activity on 69r
[24/Jan/2014:13:22:19 -0500] - read activity on 69
[24/Jan/2014:13:22:19 -0500] - conn 52 activity level = 15
[24/Jan/2014:13:22:19 -0500] - conn 52 turbo rank = 0 out of 5 conns
[24/Jan/2014:13:22:19 -0500] - conn 52 entering turbo mode
[24/Jan/2014:13:22:19 -0500] - conn 52 leaving turbo mode due to 3
[24/Jan/2014:13:22:19 -0500] - listener got signaled
[24/Jan/2014:13:22:39 -0500] - new SSL connection on 65
[24/Jan/2014:13:22:39 -0500] - new SSL connection on 69
[24/Jan/2014:13:22:39 -0500] - activity on 65r
[24/Jan/2014:13:22:39 -0500] - read activity on 65
[24/Jan/2014:13:22:39 -0500] - PR_Recv for connection 53 returns -5938 (Encountered end of file.)
[24/Jan/2014:13:22:39 -0500] - conn 53 activity level = 0
[24/Jan/2014:13:22:39 -0500] - conn 53 leaving turbo mode due to 3
[24/Jan/2014:13:22:39 -0500] - listener got signaled
[24/Jan/2014:13:22:39 -0500] - activity on 69r
[24/Jan/2014:13:22:39 -0500] - read activity on 69
[24/Jan/2014:13:22:40 -0500] - conn 54 activity level = 0
[24/Jan/2014:13:22:40 -0500] - conn 54 leaving turbo mode due to 4
[24/Jan/2014:13:22:40 -0500] - listener got signaled

[... 2 minutes later ...]
[24/Jan/2014:13:24:10 -0500] - activity on 69r
[24/Jan/2014:13:24:10 -0500] - read activity on 69
[24/Jan/2014:13:24:10 -0500] - conn 54 activity level = 1
[24/Jan/2014:13:24:10 -0500] - conn 54 turbo rank = 2 out of 5 conns
[24/Jan/2014:13:24:10 -0500] - conn 54 entering turbo mode
[24/Jan/2014:13:24:10 -0500] - => get_filter_internal
[24/Jan/2014:13:24:10 -0500] - PRESENT
[24/Jan/2014:13:24:10 -0500] - <= get_filter_internal 0
[24/Jan/2014:13:24:10 -0500] get_filter - before optimize: (objectClass=)
[24/Jan/2014:13:24:10 -0500] get_filter - after optimize: (objectClass=
)
[24/Jan/2014:13:24:10 -0500] - SRCH base="(null)" scope=0 deref=0 sizelimit=1 timelimit=10 attrsonly=0 filter="(objectClass=)" attrs="supportedSASLMechanisms defaultnamingcontext namingContexts schemanamingcontext"
[24/Jan/2014:13:24:10 -0500] index_subsys_assign_filter_decoders - before: (objectClass=
)
[24/Jan/2014:13:24:10 -0500] index_subsys_assign_filter_decoders - after: (objectClass=*)
[24/Jan/2014:13:24:10 -0500] - => slapi_vattr_filter_test_ext
[24/Jan/2014:13:24:10 -0500] - => test_substring_filter

Open Directory/Directory Services log with debugging enabled:

{{{client-0-0:~ admin$ tail -f /var/log/opendirectoryd.log | grep -B 1 "ldap1.example.com"
2014-01-24 13:21:35.576818 EST - Trigger - cancelled
2014-01-24 13:22:20.579379 EST - idle disconnected '/LDAPv3/ldap1.example.com:ldap:E5775CBD-D0C5-474A-8459-3BE8C776E6DB' to 131.142.yyy.yyy after 120 seconds
2014-01-24 13:22:20.579410 EST - Disconnecting /LDAPv3/ldap1.example.com:ldap:E5775CBD-D0C5-474A-8459-3BE8C776E6DB
2014-01-24 13:22:20.579436 EST - __odconnection_disconnect_block_invoke_0: disconnected socket 5 in connection /LDAPv3/ldap1.example.com:ldap:E5775CBD-D0C5-474A-8459-3BE8C776E6DB
--
2014-01-24 13:22:40.271536 EST - 10113.41881.41882, Node: /Local/Default, Module: PlistFile - ODQueryCreateWithNode completed
2014-01-24 13:22:40.271547 EST - 10113.41881, Node: /Search, Module: search - forwarding request to node name '/LDAPv3/ldap1.example.com'
--
2014-01-24 13:22:40.271605 EST - 10113.41881.41883, Module: search - ODQueryCreateWithNode request, NodeID: 9BAF2DE5-A52B-48DC-BD63-7B7B9BD0A62E, RecordType(s): dsRecTypeStandard:Automount, Attribute: dsAttrTypeStandard:RecordName, MatchType: EqualTo, Equality: CaseExact, Value(s): hinode,automountMapName=auto.harchive, Requested Attributes: dsAttrTypeStandard:RecordName,dsAttrTypeStandard:RecordType,dsAttrTypeStandard:GeneratedUID,dsAttrTypeStandard:AutomountInformation,dsAttrTypeStandard:AppleMetaRecordName,dsAttrTypeStandard:AppleMetaNodeLocation, Max Results: 2147483647
2014-01-24 13:22:40.271634 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - initiating reconnect for '/LDAPv3/ldap1.example.com:ldap:E5775CBD-D0C5-474A-8459-3BE8C776E6DB'
2014-01-24 13:22:40.271649 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - connection request for /LDAPv3/ldap1.example.com with read capabilities
2014-01-24 13:22:40.271658 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - trying preferred server 'ldap1.example.com' first
2014-01-24 13:22:40.271668 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - resolving 'ldap1.example.com'
2014-01-24 13:22:40.271922 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - added socket 9 for host 'ldap1.example.com:636' address '131.142.yyy.yyy' to kqueue list
2014-01-24 13:22:40.272266 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - verified connectivity to '131.142.yyy.yyy' with socket 9
2014-01-24 13:22:40.272289 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - preferred server responded - 'ldap1.example.com'
--
2014-01-24 13:22:40.286892 EST - 10251.41886, Module: SystemCache - mbr_identifier_translate completed, delivered 1 result
2014-01-24 13:22:50.271931 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - reconnect timed out after 10 seconds
2014-01-24 13:22:50.271971 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - searching for next connection to handle request
2014-01-24 13:22:50.271976 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - no other connnections to handle request
2014-01-24 13:22:50.272145 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - ODQueryCreateWithNode failed with error 'Connection failed' (2100)
2014-01-24 13:22:50.272164 EST - 10113.41881.41883, Node: /LDAPv3/ldap1.example.com, Module: search - excessive time for request - 10.001 seconds
--
2014-01-24 13:22:50.274419 EST - 10113.41889.41890, Node: /Local/Default, Module: PlistFile - ODQueryCreateWithNode completed
2014-01-24 13:22:50.274443 EST - 10113.41889, Node: /Search, Module: search - forwarding request to node name '/LDAPv3/ldap1.example.com'
--
2014-01-24 13:22:50.274536 EST - 10113.41889.41891, Module: search - ODQueryCreateWithNode request, NodeID: 9BAF2DE5-A52B-48DC-BD63-7B7B9BD0A62E, RecordType(s): dsRecTypeStandard:Automount, Attribute: dsAttrTypeStandard:RecordName, MatchType: EqualTo, Equality: CaseExact, Value(s): *,automountMapName=auto.harchive, Requested Attributes: dsAttrTypeStandard:RecordName,dsAttrTypeStandard:RecordType,dsAttrTypeStandard:GeneratedUID,dsAttrTypeStandard:AutomountInformation,dsAttrTypeStandard:AppleMetaRecordName,dsAttrTypeStandard:AppleMetaNodeLocation, Max Results: 2147483647
2014-01-24 13:23:00.275664 EST - 10113.41889.41891, Node: /LDAPv3/ldap1.example.com, Module: search - reconnect timed out after 10 seconds
2014-01-24 13:23:00.275681 EST - 10113.41889.41891, Node: /LDAPv3/ldap1.example.com, Module: search - searching for next connection to handle request
2014-01-24 13:23:00.275692 EST - 10113.41889.41891, Node: /LDAPv3/ldap1.example.com, Module: search - no other connnections to handle request
2014-01-24 13:23:00.275816 EST - 10113.41889.41891, Node: /LDAPv3/ldap1.example.com, Module: search - ODQueryCreateWithNode failed with error 'Connection failed' (2100)
2014-01-24 13:23:00.275835 EST - 10113.41889.41891, Node: /LDAPv3/ldap1.example.com, Module: search - excessive time for request - 10.001 seconds
--
2014-01-24 13:23:00.278164 EST - 10113.41894.41895, Node: /Local/Default, Module: PlistFile - ODQueryCreateWithNode completed
2014-01-24 13:23:00.278174 EST - 10113.41894, Node: /Search, Module: search - forwarding request to node name '/LDAPv3/ldap1.example.com'
--
2014-01-24 13:23:00.438884 EST - Trigger - cancelled
2014-01-24 13:23:10.279316 EST - 10113.41894.41896, Node: /LDAPv3/ldap1.example.com, Module: search - reconnect timed out after 10 seconds
2014-01-24 13:23:10.279357 EST - 10113.41894.41896, Node: /LDAPv3/ldap1.example.com, Module: search - searching for next connection to handle request
2014-01-24 13:23:10.279363 EST - 10113.41894.41896, Node: /LDAPv3/ldap1.example.com, Module: search - no other connnections to handle request
2014-01-24 13:23:10.279517 EST - 10113.41894.41896, Node: /LDAPv3/ldap1.example.com, Module: search - ODQueryCreateWithNode failed with error 'Connection failed' (2100)
2014-01-24 13:23:10.279546 EST - 10113.41894.41896, Node: /LDAPv3/ldap1.example.com, Module: search - excessive time for request - 10.001 seconds
--
2014-01-24 13:23:10.281033 EST - 10113.41897.41898, Node: /Local/Default, Module: PlistFile - ODQueryCreateWithNode completed
2014-01-24 13:23:10.281050 EST - 10113.41897, Node: /Search, Module: search - forwarding request to node name '/LDAPv3/ldap1.example.com'


Sorry for the silence on this. This issue was unseen since you set the milestone field to "N/A", which is used for closed tickets that aren't valid bugs. I've corrected the milestone so this doesn't get lost.

Since the issue is a few weeks old, I'd like to make sure it's something you are still encountering before attempting to troubleshoot. Please let us know if this is still a problem.

That's quite alright. Yes, we are still having this problem with OS X clients. I haven't gotten around to testing Snow Leopard machines, but I will be doing so this week. For now I left the standard LDAP port enabled for those clients.

Replying to [comment:3 iicodecll]:

That's quite alright. Yes, we are still having this problem with OS X clients. I haven't gotten around to testing Snow Leopard machines, but I will be doing so this week. For now I left the standard LDAP port enabled for those clients.

Did you get a chance to try Snow Leopard? Did they have the same issues?

Yes, I had a moment to test Snow Leopard. Unfortunately the same result with the Directory Service. Querying using ldapsearch works over 636.

Unrelated (?): The only difference I noticed between the Snow Leopard client and say, a Mountain Lion client, is that the GUI interface for password change utility actually works. On the later versions, it tells me the password change function has been disabled by an administrator. Password Hints also cannot be set.

Sorry for being quiet again. Could it be possible to try ssltap for debugging this issue?
https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSS/tools/NSS_Tools_ssltap

We are not able to troubleshoot since we do not have the same test environment.

We are closing this ticket for now. If you could provide us the information for debugging, please reopen this ticket with it. Thanks.

Metadata Update from @nkinder:
- Issue set to the milestone: N/A

7 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1020

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Invalid)

3 years ago

Login to comment on this ticket.

Metadata