Authentication handshake (ldap_install_tls()) fails due to underlying openssl operation failing with EINTR

[ikerexxe]

Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 7): Bug 1839972

Description of problem:
Customer seeing SSL Errors between RHEL-7.8 SSSD and IBM Directory Server
(GLD1117E)
Customer running RHEL-7.8, which are using SSSD to authenticate users against
LDAP, running IBM Directory Server.

error message shown on LDAP server
200505 18:46:12.069610 GLD1117E Unable to read SSL data from 1.8.14.218: 410 -
SSL message format is incorrect.

After the SSL handshake the LDAP Server is receiving 5 bytes expected to be the
TLS1.2 Record Application Data starting with x'170303' but instead receives 5
bytes x'30050201 01'.

It has been identified that the x30 in the first byte indicates an unencrypted
LDAP requests with a length of x05.

Version-Release number of selected component (if applicable):
sssd-1.16.4-37.el7_8.1.x86_64
sssd-ldap-1.16.4-37.el7_8.1.x86_64

How reproducible:
On customer system, it's reproducible by using some expect-script

---
spawn su - testuser
expect "ssword:"
send "secret\r"
expect "$ "
send "exit\r"
---

Steps to Reproduce:
1. login into system
2. run expect-script from above multiple times

Actual results:
Authentication sometimes fail

Expected results:
Authentication should work

Additional info:

In sssd debug logs, following error is shown.

1 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [be_resolve_server_process]
(0x0200): Found address for server LDAP.example.com: [1.7.140.12] TTL 5501
2 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400):
Constructed uri 'ldaps://LDAP.example.com/'
3 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [decide_tls_usage] (0x2000):
[ldaps://LDAP.example.com/] is a secure channel. No need to run START_TLS
4 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sssd_async_socket_init_send]
(0x4000): Using file descriptor [23] for the connection.
5 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sssd_async_socket_init_send]
(0x0400): Setting 6 seconds timeout for connecting
6 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sss_ldap_init_sys_connect_done]
(0x0020): ldap_install_tls failed: [Connect error] [unknown error]
7 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sss_ldap_init_state_destructor]
(0x0400): calling ldap_unbind_ext for ldap:[0x55ffa8c91080] sd:[23]
8 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sss_ldap_init_state_destructor]
(0x0400): closing socket [23]
9 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sdap_sys_connect_done] (0x0020):
sdap_async_connect_call request failed: [5]: Input/output error.
10 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000):
Trace: sh[0x55ffa8c921a0], connected[0], ops[(nil)], ldap[(nil)],
destructor_lock[0], release_memory[0]
11 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [_be_fo_set_port_status]
(0x8000): Setting status: PORT_NOT_WORKING. Called from:
src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_done: 1605
12 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'LDAP.example.com' as 'not working'
13 (Fri May 22 07:50:42 2020) [sssd[be[LDAP]]] [fo_set_port_status] (0x0400):
Marking port 636 of duplicate server 'LDAP.example.com' as 'not working'


Could this be related to the "FIXME" note in code [1]

/* FIXME: take care that ldap_install_tls might block */
    ret = ldap_install_tls(state->sh->ldap);
    if (ret != LDAP_SUCCESS) {



[1]: https://github.com/SSSD/sssd/blob/d8d743870c459b5ff283c89d78b70d1684bd19a9
/src/providers/ldap/sdap_async_connection.c#L403

[pbrezina]

Pushed PR: #5532

• master
  • da55e3e - ldap: retry ldap_install_tls() when watchdog interruption

[pbrezina]

Pushed PR: #5595

• sssd-1-16
  • ee16c60 - ldap: retry ldap_install_tls() when watchdog interruption