Bug 1893870

Description of problem:

See issue is explained in detailed on FreeeIPA upstream bug https://pagure.io/freeipa/issue/8544.

The root cause of the problem is NSPR's PR_WaitCondVar() implementation. On pthread platforms the function is built on top of pthread_cond_timedwait. The function takes an absolute time. Both pthread_cond_timedwait and PR_WaitCondVar internal helper pt_TimedWait default to realtime clock which is subject to clock changes. pthread_condattr_setclock with CLOCK_MONOTONIC could be used to change the clock source from real to monotonic clock. This fix would require changes internal APIs or even a new API in NSPR.

Summary:

    FreeIPA server with DNS role use local BIND DNS instance as only DNS server.
    DNS facilities are not available until 389-DS, KDC, and BIND DNS are up and working.
    chronyd cannot synchronize clocks until DNS is up.
    Kerberos / GSSAPI doesn't work correctly when clocks of two hosts are way out of sync.
    When chronyd eventually syncs time, a backward jump confuses the sleep timer of the thread sync condition. This can extend a timed condition wait from a few seconds to several hours.

Package Version and Platform:

    Platform: Fedora
    Package and version: 389-ds-base-1.4.3.12-1.fc32.x86_64

Steps to Reproduce
Steps to reproduce the behavior:

    Install IPA cluster with multiple replications and DNS on each server
    change hardware clock on one server so chronyd has to adjust clock by 2 hours on boot
    reboot server

Expected results
Replication session backing off timer is not affected by clock jumps. For example a wait timeout of 60 seconds is not shortened or prolonged by real time clock changes. Instead it uses a monotonic, stable clock source.

Logs with replication debug information

Replication connection fails with GSSAPI auth problem because remote server does not like our Kerboers ticket. This is expected behavior. 389-DS retries a couple of times with increasing back off time:

[18/Oct/2020:20:05:57.131884318 +0200] - DEBUG - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=meTovm-178.ipa.example" (vm-178:389) - Replication bind with GSSAPI auth failed: LDAP error 49 (Invalid credentials) (SASL(-13): authentication failure: GSSAPI Failure: gss_accept_sec_context)
[18/Oct/2020:20:05:57.134281879 +0200] - DEBUG - NSMMReplicationPlugin - close_connection_internal - agmt="cn=meTovm-178.ipa.example" (vm-178:389) - Disconnected from the consumer
[18/Oct/2020:20:05:57.135706884 +0200] - DEBUG - NSMMReplicationPlugin - conn_start_linger -agmt="cn=meTovm-178.ipa.example" (vm-178:389) - Beginning linger on the connection
[18/Oct/2020:20:05:57.137076558 +0200] - DEBUG - NSMMReplicationPlugin - conn_start_linger - agmt="cn=meTovm-178.ipa.example" (vm-178:389) - No linger on the closed conn
[18/Oct/2020:20:05:57.138557059 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTovm-178.ipa.example" (vm-178:389): Replication session backing off for 48 seconds

Seconds after last back off chronyd successfully connects to a NTP server and adjusts the clock by almost 2 hours.

[18/Oct/2020:18:06:04.871577135 +0200] ...

For over 2 hours there is no log entry related to the meTovm-178 agreement. Over 2 hours later the retry timer kicks in and resumes replication:

[18/Oct/2020:20:06:45.899245023 +0200] - INFO - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=vm-171-245.ipa.example-to-vm-171-180.ipa.example" (vm-171-180:389): Replication bind with GSSAPI auth resumed
...
[18/Oct/2020:20:06:45.947839525 +0200] - DEBUG - NSMMReplicationPlugin - acquire_replica - agmt="cn=meTovm-178.ipa.example" (vm-178:389): Replica was successfully acquired.
[18/Oct/2020:20:06:45.949733829 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTovm-178.ipa.example" (vm-178:389): State: backoff -> sending_updates