Hi Everyone,
We're running a cluster of VM's running 389-Directory/1.3.9.1 B2019.164.1418 on RHEL7.7. Some are providers, which replicate to a bunch of hubs (which provide authentication services), which replicate in turn to a bunch of consumers (which provide support for longer running queries). Of late, we've a few clients have noted timed out connections. When we look in our logs we see things like:
[23/Dec/2019:00:21:50.760643645 -0800] conn=7827580 fd=469 slot=469 SSL connection from <their IP> to <our IP> [23/Dec/2019:00:21:50.764149645 -0800] conn=7827580 TLS1.2 256-bit AES-GCM <no other transactions on conn=7827580, until the client times out the connection> [23/Dec/2019:00:22:05.763868515 -0800] conn=7827580 op=-1 fd=469 closed - Encountered end of file.
Others connections are made and operate just fine between the opening and closing of the timed-out connection.
Would anyone know what this could be/what we could check?
Thanks, Trev
are the LDAP clients always the same? or is it more like an LDAP server does not accept TLS or SSL connections at all? could it be a temporary situation while some large searches are processed? are there load balancers in between? check for LDAP server descriptors and system entropy. check for nsslapd-enable-nunc-stans: off ldapsearch -D "cn=directory manager" -W -b cn=config -s base nsslapd-enable-nunc-stans may be take a pstack Thanks, M.
On Mon, Dec 23, 2019 at 3:08 PM Trevor Fong tjfong@gmail.com wrote:
Hi Everyone,
We're running a cluster of VM's running 389-Directory/1.3.9.1 B2019.164.1418 on RHEL7.7. Some are providers, which replicate to a bunch of hubs (which provide authentication services), which replicate in turn to a bunch of consumers (which provide support for longer running queries). Of late, we've a few clients have noted timed out connections. When we look in our logs we see things like:
[23/Dec/2019:00:21:50.760643645 -0800] conn=7827580 fd=469 slot=469 SSL connection from <their IP> to <our IP> [23/Dec/2019:00:21:50.764149645 -0800] conn=7827580 TLS1.2 256-bit AES-GCM <no other transactions on conn=7827580, until the client times out the connection> [23/Dec/2019:00:22:05.763868515 -0800] conn=7827580 op=-1 fd=469 closed - Encountered end of file.
Others connections are made and operate just fine between the opening and closing of the timed-out connection.
Would anyone know what this could be/what we could check?
Thanks, Trev _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
Hi Marc,
Thanks for your response. Yes - it's always the 4 hubs that are responsible for authentication. Apart from the following recurring errors in the errors log, there aren't any other signs of stress on the system - CPU and memory look OK; nothing unexpected in /var/log/messages:
[24/Dec/2019:07:55:36.298853461 -0800] - ERR - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=hub-<node name>" (<node name>:636) - Replication bind with SIMPLE auth failed: LDAP error -5 (Timed out) () [24/Dec/2019:07:55:39.323604233 -0800] - INFO - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=hub-<node name>" (<node name>:636): Replication bind with SIMPLE auth resumed
Thanks, Trev
Also, It could be a temporary situation caused by some long running searches; I'm crawling the logs, but they're volumous and trying to make correspondences between 4 servers is confusing and time consuming. I'm sure I'm missing stuff. Would you have any advice on what to check for? Those 4 hubs are fronted by a load-balancer. nsslapd-enable-nunc-stans is off The servers involved aren't hanging, just some connections intermittently; other connections still happen fine while the one that hangs waits for timeout, so taking a pstack or gdb won't necessarily show anything.
check for LDAP server descriptors and system entropy.
How do I go about checking on this?
Thanks, Trev
I was looking at the RH DS docs and found this page on enabling auto tuning of threads https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/ht... It mentions DS 10.11. Does anyone know if that covers the version of 389 DS I'm running: 389-Directory/1.3.9.1 B2019.164.1418?
Thanks, Trev
On Tue, 24 Dec 2019 at 08:37, Trevor Fong tjfong@gmail.com wrote:
Also, It could be a temporary situation caused by some long running searches; I'm crawling the logs, but they're volumous and trying to make correspondences between 4 servers is confusing and time consuming. I'm sure I'm missing stuff. Would you have any advice on what to check for? Those 4 hubs are fronted by a load-balancer. nsslapd-enable-nunc-stans is off The servers involved aren't hanging, just some connections intermittently; other connections still happen fine while the one that hangs waits for timeout, so taking a pstack or gdb won't necessarily show anything.
check for LDAP server descriptors and system entropy.
How do I go about checking on this?
Thanks, Trev _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
Happy New Year, everyone!
Further to this, I added connection management loglevel to the errorlog level and managed to capture the output during one of the events when the connection seems to stall. Would anyone be able to help me make sense of it?
Thanks a lot, Trevor Fong
Access log: [02/Jan/2020:08:21:00.925703124 -0800] conn=258144 fd=263 slot=263 SSL connection from <cleint ip> to <host ip> [02/Jan/2020:08:21:00.934435506 -0800] conn=258144 TLS1.2 256-bit AES-GCM < expecting other transactions with conn=258144 but nothing happens until the following, when the connection is eventually timed out (600 sec) and broken by the client> [02/Jan/2020:08:31:01.024762657 -0800] conn=258144 op=-1 fd=263 closed - Encountered end of file.
Error log: [02/Jan/2020:08:21:00.924588379 -0800] - DEBUG - connection_reset - new SSL connection on 263 [02/Jan/2020:08:21:00.927088611 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:21:00.927961983 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:21:00.932285653 -0800] - DEBUG - connection_read_operation - connection 258144 waited 1 times for read to be ready [02/Jan/2020:08:21:00.934724384 -0800] - DEBUG - connection_read_operation - connection 258144 waited 2 times for read to be ready [02/Jan/2020:08:21:01.035814543 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 4 - thread_turbo_flag 0 more_data 0 ops_initiated 1 refcnt 2 flags 17 [02/Jan/2020:08:21:01.036940723 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 0 [02/Jan/2020:08:21:01.037824240 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 4 [02/Jan/2020:08:21:01.038667951 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:21:01.039407337 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 … [02/Jan/2020:08:31:01.018473459 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:31:01.020162681 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:31:01.021136264 -0800] - DEBUG - connection_read_operation - PR_Recv for connection 258144 returns -5938 (Encountered end of file.) [02/Jan/2020:08:31:01.022435629 -0800] - DEBUG - disconnect_server_nomutex_ext - Setting conn 258144 fd=263 to be disconnected: reason -5938 [02/Jan/2020:08:31:01.024785254 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 3 - thread_turbo_flag 0 more_data 0 ops_initiated 2 refcnt 2 flags 19 [02/Jan/2020:08:31:01.026135420 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 1 [02/Jan/2020:08:31:01.027294400 -0800] - DEBUG - connection_enter_leave_turbo - conn 258144 turbo rank = 41 out of 841 conns [02/Jan/2020:08:31:01.028297819 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 3 [02/Jan/2020:08:31:01.029284720 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:31:01.034004014 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 [02/Jan/2020:08:31:01.036209375 -0800] - DEBUG - clear_signal - Listener got signaled [02/Jan/2020:08:31:01.037395981 -0800] - DEBUG - connection_table_move_connection_out_of_active_list - Moved conn 263 out of active list and freed
Is it possible that that application is pro-actively creating LDAP connections that it does not use? This scenario might happen if the application is using connection pooling.
-----Original Message----- From: Trevor Fong tjfong@gmail.com Sent: Thursday, January 2, 2020 10:16 AM To: 389-users@lists.fedoraproject.org Subject: [389-users] Re: Connections Opened but No BIND Received
Happy New Year, everyone!
Further to this, I added connection management loglevel to the errorlog level and managed to capture the output during one of the events when the connection seems to stall. Would anyone be able to help me make sense of it?
Thanks a lot, Trevor Fong
Access log: [02/Jan/2020:08:21:00.925703124 -0800] conn=258144 fd=263 slot=263 SSL connection from <cleint ip> to <host ip> [02/Jan/2020:08:21:00.934435506 -0800] conn=258144 TLS1.2 256-bit AES-GCM < expecting other transactions with conn=258144 but nothing happens until the following, when the connection is eventually timed out (600 sec) and broken by the client> [02/Jan/2020:08:31:01.024762657 -0800] conn=258144 op=-1 fd=263 closed - Encountered end of file.
Error log: [02/Jan/2020:08:21:00.924588379 -0800] - DEBUG - connection_reset - new SSL connection on 263 [02/Jan/2020:08:21:00.927088611 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:21:00.927961983 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:21:00.932285653 -0800] - DEBUG - connection_read_operation - connection 258144 waited 1 times for read to be ready [02/Jan/2020:08:21:00.934724384 -0800] - DEBUG - connection_read_operation - connection 258144 waited 2 times for read to be ready [02/Jan/2020:08:21:01.035814543 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 4 - thread_turbo_flag 0 more_data 0 ops_initiated 1 refcnt 2 flags 17 [02/Jan/2020:08:21:01.036940723 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 0 [02/Jan/2020:08:21:01.037824240 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 4 [02/Jan/2020:08:21:01.038667951 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:21:01.039407337 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 … [02/Jan/2020:08:31:01.018473459 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:31:01.020162681 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:31:01.021136264 -0800] - DEBUG - connection_read_operation - PR_Recv for connection 258144 returns -5938 (Encountered end of file.) [02/Jan/2020:08:31:01.022435629 -0800] - DEBUG - disconnect_server_nomutex_ext - Setting conn 258144 fd=263 to be disconnected: reason -5938 [02/Jan/2020:08:31:01.024785254 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 3 - thread_turbo_flag 0 more_data 0 ops_initiated 2 refcnt 2 flags 19 [02/Jan/2020:08:31:01.026135420 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 1 [02/Jan/2020:08:31:01.027294400 -0800] - DEBUG - connection_enter_leave_turbo - conn 258144 turbo rank = 41 out of 841 conns [02/Jan/2020:08:31:01.028297819 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 3 [02/Jan/2020:08:31:01.029284720 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:31:01.034004014 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 [02/Jan/2020:08:31:01.036209375 -0800] - DEBUG - clear_signal - Listener got signaled [02/Jan/2020:08:31:01.037395981 -0800] - DEBUG - connection_table_move_connection_out_of_active_list - Moved conn 263 out of active list and freed _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Guidelines: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Archives: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... This communication is the property of CenturyLink and may contain confidential or privileged information. Unauthorized use of this communication is strictly prohibited and may be unlawful. If you have received this communication in error, please immediately notify the sender by reply e-mail and destroy all copies of the communication and any attachments.
Hi Steve,
We see it happening with replication connections from other 389 DS servers in the cluster (but because it is multi-master, other replications masters' succeed, so its OK). However, we also see it with other clients - they will initiate a connection, but the connection will hang and the client will time it out.
Thanks, Trev
On Thu, 2 Jan 2020 at 09:43, Vandenburgh, Steve Y < Steve.Vandenburgh@centurylink.com> wrote:
Is it possible that that application is pro-actively creating LDAP connections that it does not use? This scenario might happen if the application is using connection pooling.
-----Original Message----- From: Trevor Fong tjfong@gmail.com Sent: Thursday, January 2, 2020 10:16 AM To: 389-users@lists.fedoraproject.org Subject: [389-users] Re: Connections Opened but No BIND Received
Happy New Year, everyone!
Further to this, I added connection management loglevel to the errorlog level and managed to capture the output during one of the events when the connection seems to stall. Would anyone be able to help me make sense of it?
Thanks a lot, Trevor Fong
Access log: [02/Jan/2020:08:21:00.925703124 -0800] conn=258144 fd=263 slot=263 SSL connection from <cleint ip> to <host ip> [02/Jan/2020:08:21:00.934435506 -0800] conn=258144 TLS1.2 256-bit AES-GCM < expecting other transactions with conn=258144 but nothing happens until the following, when the connection is eventually timed out (600 sec) and broken by the client> [02/Jan/2020:08:31:01.024762657 -0800] conn=258144 op=-1 fd=263 closed - Encountered end of file.
Error log: [02/Jan/2020:08:21:00.924588379 -0800] - DEBUG - connection_reset - new SSL connection on 263 [02/Jan/2020:08:21:00.927088611 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:21:00.927961983 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:21:00.932285653 -0800] - DEBUG - connection_read_operation
- connection 258144 waited 1 times for read to be ready
[02/Jan/2020:08:21:00.934724384 -0800] - DEBUG - connection_read_operation
- connection 258144 waited 2 times for read to be ready
[02/Jan/2020:08:21:01.035814543 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 4 - thread_turbo_flag 0 more_data 0 ops_initiated 1 refcnt 2 flags 17 [02/Jan/2020:08:21:01.036940723 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 0 [02/Jan/2020:08:21:01.037824240 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 4 [02/Jan/2020:08:21:01.038667951 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:21:01.039407337 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 … [02/Jan/2020:08:31:01.018473459 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:31:01.020162681 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:31:01.021136264 -0800] - DEBUG - connection_read_operation
- PR_Recv for connection 258144 returns -5938 (Encountered end of file.)
[02/Jan/2020:08:31:01.022435629 -0800] - DEBUG - disconnect_server_nomutex_ext - Setting conn 258144 fd=263 to be disconnected: reason -5938 [02/Jan/2020:08:31:01.024785254 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 3 - thread_turbo_flag 0 more_data 0 ops_initiated 2 refcnt 2 flags 19 [02/Jan/2020:08:31:01.026135420 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 1 [02/Jan/2020:08:31:01.027294400 -0800] - DEBUG - connection_enter_leave_turbo - conn 258144 turbo rank = 41 out of 841 conns [02/Jan/2020:08:31:01.028297819 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 3 [02/Jan/2020:08:31:01.029284720 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:31:01.034004014 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 [02/Jan/2020:08:31:01.036209375 -0800] - DEBUG - clear_signal - Listener got signaled [02/Jan/2020:08:31:01.037395981 -0800] - DEBUG - connection_table_move_connection_out_of_active_list - Moved conn 263 out of active list and freed _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Guidelines: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Archives: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... This communication is the property of CenturyLink and may contain confidential or privileged information. Unauthorized use of this communication is strictly prohibited and may be unlawful. If you have received this communication in error, please immediately notify the sender by reply e-mail and destroy all copies of the communication and any attachments. _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
the build string 389-Directory/1.3.9.1 B2019.164.1418 corresponds to a RHEL-7.7 with RHDS-10.4 to verify: cat /etc/redhat-release; rpm -q redhat-ds 389-ds-base
the access and errors log snippets are showing a "normal" timeout after 10mn, when there is no activity, and they do not really provide more information.
for the system entropy, check with cat /proc/sys/kernel/random/entropy_avail systemctl status rngd
if for example, the system entropy is less than 1K, crypto operations may be extremely slow, and rngd should be running, like for example: mkdir -p /etc/systemd/system/rngd.service.d cat > /etc/systemd/system/rngd.service.d/entropy-source.conf << EOF [Service] ExecStart=/sbin/rngd -f -r /dev/urandom -o /dev/random EOF systemctl daemon-reload systemctl enable rngd systemctl start rngd systemctl status rngd cat /proc/sys/kernel/random/entropy_avail
If the ns-slapd stops responding, try to set the attribute nsslapd-ioblocktimeout under cn=config to a smaller value, like for example, 15 seconds / 15000 ldapmodify -D "cn=directory manager" -W dn: cn=config changetype: modify replace: nsslapd-ioblocktimeout nsslapd-ioblocktimeout: 15000
<press enter twice, then control-D>
Thanks, M.
On Thu, Jan 2, 2020 at 11:28 AM Trevor Fong tjfong@gmail.com wrote:
Hi Steve,
We see it happening with replication connections from other 389 DS servers in the cluster (but because it is multi-master, other replications masters' succeed, so its OK). However, we also see it with other clients - they will initiate a connection, but the connection will hang and the client will time it out.
Thanks, Trev
On Thu, 2 Jan 2020 at 09:43, Vandenburgh, Steve Y < Steve.Vandenburgh@centurylink.com> wrote:
Is it possible that that application is pro-actively creating LDAP connections that it does not use? This scenario might happen if the application is using connection pooling.
-----Original Message----- From: Trevor Fong tjfong@gmail.com Sent: Thursday, January 2, 2020 10:16 AM To: 389-users@lists.fedoraproject.org Subject: [389-users] Re: Connections Opened but No BIND Received
Happy New Year, everyone!
Further to this, I added connection management loglevel to the errorlog level and managed to capture the output during one of the events when the connection seems to stall. Would anyone be able to help me make sense of it?
Thanks a lot, Trevor Fong
Access log: [02/Jan/2020:08:21:00.925703124 -0800] conn=258144 fd=263 slot=263 SSL connection from <cleint ip> to <host ip> [02/Jan/2020:08:21:00.934435506 -0800] conn=258144 TLS1.2 256-bit AES-GCM < expecting other transactions with conn=258144 but nothing happens until the following, when the connection is eventually timed out (600 sec) and broken by the client> [02/Jan/2020:08:31:01.024762657 -0800] conn=258144 op=-1 fd=263 closed - Encountered end of file.
Error log: [02/Jan/2020:08:21:00.924588379 -0800] - DEBUG - connection_reset - new SSL connection on 263 [02/Jan/2020:08:21:00.927088611 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:21:00.927961983 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:21:00.932285653 -0800] - DEBUG - connection_read_operation - connection 258144 waited 1 times for read to be ready [02/Jan/2020:08:21:00.934724384 -0800] - DEBUG - connection_read_operation - connection 258144 waited 2 times for read to be ready [02/Jan/2020:08:21:01.035814543 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 4 - thread_turbo_flag 0 more_data 0 ops_initiated 1 refcnt 2 flags 17 [02/Jan/2020:08:21:01.036940723 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 0 [02/Jan/2020:08:21:01.037824240 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 4 [02/Jan/2020:08:21:01.038667951 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:21:01.039407337 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 … [02/Jan/2020:08:31:01.018473459 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:31:01.020162681 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:31:01.021136264 -0800] - DEBUG - connection_read_operation - PR_Recv for connection 258144 returns -5938 (Encountered end of file.) [02/Jan/2020:08:31:01.022435629 -0800] - DEBUG - disconnect_server_nomutex_ext - Setting conn 258144 fd=263 to be disconnected: reason -5938 [02/Jan/2020:08:31:01.024785254 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 3 - thread_turbo_flag 0 more_data 0 ops_initiated 2 refcnt 2 flags 19 [02/Jan/2020:08:31:01.026135420 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 1 [02/Jan/2020:08:31:01.027294400 -0800] - DEBUG - connection_enter_leave_turbo - conn 258144 turbo rank = 41 out of 841 conns [02/Jan/2020:08:31:01.028297819 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 3 [02/Jan/2020:08:31:01.029284720 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:31:01.034004014 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 [02/Jan/2020:08:31:01.036209375 -0800] - DEBUG - clear_signal - Listener got signaled [02/Jan/2020:08:31:01.037395981 -0800] - DEBUG - connection_table_move_connection_out_of_active_list - Moved conn 263 out of active list and freed _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Guidelines: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Archives: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... This communication is the property of CenturyLink and may contain confidential or privileged information. Unauthorized use of this communication is strictly prohibited and may be unlawful. If you have received this communication in error, please immediately notify the sender by reply e-mail and destroy all copies of the communication and any attachments. _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
On 3 Jan 2020, at 07:14, Marc Sauton msauton@redhat.com wrote:
the build string 389-Directory/1.3.9.1 B2019.164.1418 corresponds to a RHEL-7.7 with RHDS-10.4 to verify: cat /etc/redhat-release; rpm -q redhat-ds 389-ds-base
the access and errors log snippets are showing a "normal" timeout after 10mn, when there is no activity, and they do not really provide more information.
for the system entropy, check with cat /proc/sys/kernel/random/entropy_avail systemctl status rngd
if for example, the system entropy is less than 1K, crypto operations may be extremely slow, and rngd should be running, like for example: mkdir -p /etc/systemd/system/rngd.service.d cat > /etc/systemd/system/rngd.service.d/entropy-source.conf << EOF [Service] ExecStart=/sbin/rngd -f -r /dev/urandom -o /dev/random EOF systemctl daemon-reload systemctl enable rngd systemctl start rngd systemctl status rngd cat /proc/sys/kernel/random/entropy_avail
If the ns-slapd stops responding, try to set the attribute nsslapd-ioblocktimeout under cn=config to a smaller value, like for example, 15 seconds / 15000 ldapmodify -D "cn=directory manager" -W dn: cn=config changetype: modify replace: nsslapd-ioblocktimeout nsslapd-ioblocktimeout: 15000
<press enter twice, then control-D>
I would hope it's not this. But my question is why is anything using /dev/random. It's been debunked for *years* that /dev/random is somehow "more random" and that /dev/urandom should always be used.
Is this a bug in NSS then for using incorrect rng?
Thanks, M.
On Thu, Jan 2, 2020 at 11:28 AM Trevor Fong tjfong@gmail.com wrote: Hi Steve,
We see it happening with replication connections from other 389 DS servers in the cluster (but because it is multi-master, other replications masters' succeed, so its OK). However, we also see it with other clients - they will initiate a connection, but the connection will hang and the client will time it out.
Thanks, Trev
On Thu, 2 Jan 2020 at 09:43, Vandenburgh, Steve Y Steve.Vandenburgh@centurylink.com wrote: Is it possible that that application is pro-actively creating LDAP connections that it does not use? This scenario might happen if the application is using connection pooling.
-----Original Message----- From: Trevor Fong tjfong@gmail.com Sent: Thursday, January 2, 2020 10:16 AM To: 389-users@lists.fedoraproject.org Subject: [389-users] Re: Connections Opened but No BIND Received
Happy New Year, everyone!
Further to this, I added connection management loglevel to the errorlog level and managed to capture the output during one of the events when the connection seems to stall. Would anyone be able to help me make sense of it?
Thanks a lot, Trevor Fong
Access log: [02/Jan/2020:08:21:00.925703124 -0800] conn=258144 fd=263 slot=263 SSL connection from <cleint ip> to <host ip> [02/Jan/2020:08:21:00.934435506 -0800] conn=258144 TLS1.2 256-bit AES-GCM < expecting other transactions with conn=258144 but nothing happens until the following, when the connection is eventually timed out (600 sec) and broken by the client> [02/Jan/2020:08:31:01.024762657 -0800] conn=258144 op=-1 fd=263 closed - Encountered end of file.
Error log: [02/Jan/2020:08:21:00.924588379 -0800] - DEBUG - connection_reset - new SSL connection on 263 [02/Jan/2020:08:21:00.927088611 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:21:00.927961983 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:21:00.932285653 -0800] - DEBUG - connection_read_operation - connection 258144 waited 1 times for read to be ready [02/Jan/2020:08:21:00.934724384 -0800] - DEBUG - connection_read_operation - connection 258144 waited 2 times for read to be ready [02/Jan/2020:08:21:01.035814543 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 4 - thread_turbo_flag 0 more_data 0 ops_initiated 1 refcnt 2 flags 17 [02/Jan/2020:08:21:01.036940723 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 0 [02/Jan/2020:08:21:01.037824240 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 4 [02/Jan/2020:08:21:01.038667951 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:21:01.039407337 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 … [02/Jan/2020:08:31:01.018473459 -0800] - DEBUG - connection_table_dump_activity_to_errors_log - activity on 263r [02/Jan/2020:08:31:01.020162681 -0800] - DEBUG - handle_pr_read_ready - read activity on 263 [02/Jan/2020:08:31:01.021136264 -0800] - DEBUG - connection_read_operation - PR_Recv for connection 258144 returns -5938 (Encountered end of file.) [02/Jan/2020:08:31:01.022435629 -0800] - DEBUG - disconnect_server_nomutex_ext - Setting conn 258144 fd=263 to be disconnected: reason -5938 [02/Jan/2020:08:31:01.024785254 -0800] - DEBUG - connection_threadmain - conn 258144 read not ready due to 3 - thread_turbo_flag 0 more_data 0 ops_initiated 2 refcnt 2 flags 19 [02/Jan/2020:08:31:01.026135420 -0800] - DEBUG - connection_check_activity_level - conn 258144 activity level = 1 [02/Jan/2020:08:31:01.027294400 -0800] - DEBUG - connection_enter_leave_turbo - conn 258144 turbo rank = 41 out of 841 conns [02/Jan/2020:08:31:01.028297819 -0800] - DEBUG - connection_threadmain - conn 258144 leaving turbo mode due to 3 [02/Jan/2020:08:31:01.029284720 -0800] - DEBUG - connection_threadmain - conn 258144 check more_data 0 thread_turbo_flag 0repl_conn_bef 0, repl_conn_now 0 [02/Jan/2020:08:31:01.034004014 -0800] - DEBUG - connection_make_readable_nolock - making readable conn 258144 fd=263 [02/Jan/2020:08:31:01.036209375 -0800] - DEBUG - clear_signal - Listener got signaled [02/Jan/2020:08:31:01.037395981 -0800] - DEBUG - connection_table_move_connection_out_of_active_list - Moved conn 263 out of active list and freed _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Guidelines: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... List Archives: https://imss91-ctp.trendmicro.com:443/wis/clicktime/v1/query?url=https%3a%2f... This communication is the property of CenturyLink and may contain confidential or privileged information. Unauthorized use of this communication is strictly prohibited and may be unlawful. If you have received this communication in error, please immediately notify the sender by reply e-mail and destroy all copies of the communication and any attachments. _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject.... _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject.... _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
— Sincerely,
William Brown
Senior Software Engineer, 389 Directory Server SUSE Labs
Hi Everyone, It looks like entropy was OK; /proc/sys/kernel/random/entropy_avail was about ~3500 on each vm. rngd was not installed. However the issue went away around lunchtime of 2-Jan! It does not appear to be load related as it is slightly higher now than when we were seeing those issues. We're looking at the network now...
Thanks everyone, and Happy New Year :) Trev
On 7 Jan 2020, at 06:05, Trevor Fong trevor.fong@ubc.ca wrote:
Hi Everyone, It looks like entropy was OK; /proc/sys/kernel/random/entropy_avail was about ~3500 on each vm. rngd was not installed. However the issue went away around lunchtime of 2-Jan! It does not appear to be load related as it is slightly higher now than when we were seeing those issues. We're looking at the network now...
We'd be keen to hear if there is a follow up or solution you found, so let us know!
Thanks everyone, and Happy New Year :)
Happy new year to you also
Trev _______________________________________________ 389-users mailing list -- 389-users@lists.fedoraproject.org To unsubscribe send an email to 389-users-leave@lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproject....
— Sincerely,
William Brown
Senior Software Engineer, 389 Directory Server SUSE Labs
389-users@lists.fedoraproject.org
-
Marc Sauton -
Trevor Fong -
Trevor Fong -
Vandenburgh, Steve Y -
William Brown