Yesterday I installed a replica on a clean Rocky 9 system. No issues
at all. Everything
seemed to work fine.
Today the machine was rebooted (no dnf updates, no system changes) and
ipa could not start anymore.
ipactl start -d says:
Starting Directory Service
ipa: DEBUG: Starting external process
ipa: DEBUG: args=['/bin/systemctl', 'start',
'dirsrv(a)HQ-SPINQUE-COM.service']
ipa: DEBUG: Process finished, return code=0
ipa: DEBUG: Starting external process
ipa: DEBUG: args=['/bin/systemctl', 'is-active',
'dirsrv(a)HQ-SPINQUE-COM.service']
ipa: DEBUG: Process finished, return code=0
ipa: DEBUG: stdout=active
ipa: DEBUG: stderr=
ipa: DEBUG: wait_for_open_ports: localhost [389] timeout 120
ipa: DEBUG: waiting for port: 389
ipa: DEBUG: Failed to connect to port 389 tcp on ::1
ipa: DEBUG: File
"/usr/lib/python3.9/site-packages/ipaserver/install/installutils.py",
line 781, in run_script
return_value = main_function()
File "/usr/lib/python3.9/site-packages/ipaserver/install/ipactl.py",
line 739, in main
ipa_restart(options)
File "/usr/lib/python3.9/site-packages/ipaserver/install/ipactl.py",
line 499, in ipa_restart
raise IpactlError("Failed to start Directory Service: " + str(e))
ipa: DEBUG: The ipactl command failed, exception: IpactlError: Failed
to start Directory Service: Timeout exceeded
Failed to start Directory Service: Timeout exceeded
/var/log/dirsrv/slapd-HQ-SPINQUE-COM/errors says:
[17/Nov/2022:17:22:21.074990853 +0100] - INFO - slapd_extract_cert -
CA CERT NAME:
HQ.SPINQUE.COM <
http://HQ.SPINQUE.COM> IPA CA
[17/Nov/2022:17:22:21.668775045 +0100] - WARN - Security
Initialization - SSL alert: Sending pin request to SVRCore. You may
need to run systemd-tty-ask-password-agent to provide the password if
pin.txt does not exist.
[17/Nov/2022:17:22:22.295325169 +0100] - INFO - slapd_extract_cert -
SERVER CERT NAME: Server-Cert
[17/Nov/2022:17:22:23.275812957 +0100] - INFO - Security
Initialization - SSL info: Enabling default cipher set.
[17/Nov/2022:17:22:26.090728693 +0100] - INFO - Security
Initialization - SSL info: Configured NSS Ciphers
[17/Nov/2022:17:22:26.771211814 +0100] - INFO - Security
Initialization - SSL info: TLS_AES_128_GCM_SHA256: enabled
[17/Nov/2022:17:22:28.438124063 +0100] - INFO - Security
Initialization - SSL info: TLS_CHACHA20_POLY1305_SHA256: enabled
[17/Nov/2022:17:22:28.928766931 +0100] - INFO - Security
Initialization - SSL info: TLS_AES_256_GCM_SHA384: enabled
[17/Nov/2022:17:22:29.544178747 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256:
enabled
[17/Nov/2022:17:22:30.099717701 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[17/Nov/2022:17:22:30.657974763 +0100] - INFO - Security
Initialization - SSL info:
TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[17/Nov/2022:17:22:31.245996850 +0100] - INFO - Security
Initialization - SSL info:
TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[17/Nov/2022:17:22:31.790186166 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384:
enabled
[17/Nov/2022:17:22:32.205374722 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[17/Nov/2022:17:22:32.771492861 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled
[17/Nov/2022:17:22:33.139528386 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled
[17/Nov/2022:17:22:33.392948327 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled
[17/Nov/2022:17:22:33.420924018 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256:
enabled
[17/Nov/2022:17:22:33.468560401 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[17/Nov/2022:17:22:33.524578902 +0100] - INFO - Security
Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled
[17/Nov/2022:17:22:33.769874334 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[17/Nov/2022:17:22:34.596047264 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256:
enabled
[17/Nov/2022:17:22:35.137255640 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[17/Nov/2022:17:22:35.938316117 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled
[17/Nov/2022:17:22:36.492933614 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[17/Nov/2022:17:22:37.059388478 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled
[17/Nov/2022:17:22:37.497954414 +0100] - INFO - Security
Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled
[17/Nov/2022:17:22:37.899521527 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_128_GCM_SHA256: enabled
[17/Nov/2022:17:22:38.340476108 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_256_GCM_SHA384: enabled
[17/Nov/2022:17:22:38.910037361 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_128_CBC_SHA: enabled
[17/Nov/2022:17:22:39.572044273 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_128_CBC_SHA256: enabled
[17/Nov/2022:17:22:40.025517184 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_256_CBC_SHA: enabled
[17/Nov/2022:17:22:40.426814987 +0100] - INFO - Security
Initialization - SSL info: TLS_RSA_WITH_AES_256_CBC_SHA256: enabled
[17/Nov/2022:17:22:40.972957570 +0100] - INFO - Security
Initialization - slapd_ssl_init2 - Configured SSL version range: min:
TLS1.2, max: TLS1.3
[17/Nov/2022:17:22:41.780274052 +0100] - INFO - Security
Initialization - slapd_ssl_init2 - NSS adjusted SSL version range:
min: TLS1.2, max: TLS1.3
[17/Nov/2022:17:22:42.112229404 +0100] - INFO - main -
389-Directory/2.0.14 B2022.028.0000 starting up
[17/Nov/2022:17:22:42.255025476 +0100] - INFO - main - Setting the
maximum file descriptor limit to: 524288
[17/Nov/2022:17:22:42.302617003 +0100] - ERR - allow_operation -
Component identity is NULL
[17/Nov/2022:17:22:42.487999340 +0100] - ERR - allow_operation -
Component identity is NULL
[17/Nov/2022:17:22:43.468192243 +0100] - INFO - PBKDF2_SHA256 - Based
on CPU performance, chose 2048 rounds
[17/Nov/2022:17:22:44.183513462 +0100] - INFO -
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[17/Nov/2022:17:22:44.624731155 +0100] - INFO -
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[17/Nov/2022:17:22:45.253918872 +0100] - INFO -
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[17/Nov/2022:17:22:45.858243466 +0100] - NOTICE - bdb_start_autotune -
found 4009000k physical memory
[17/Nov/2022:17:22:46.481252068 +0100] - NOTICE - bdb_start_autotune -
found 2327312k available
[17/Nov/2022:17:22:47.020077517 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: db cache: 250562k
[17/Nov/2022:17:22:47.566361446 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: userRoot entry cache (3 total): 262144k
[17/Nov/2022:17:22:48.138811388 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: userRoot dn cache (3 total): 65536k
[17/Nov/2022:17:22:48.755496155 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: ipaca entry cache (3 total): 262144k
[17/Nov/2022:17:22:49.175857218 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: ipaca dn cache (3 total): 65536k
[17/Nov/2022:17:22:49.566843365 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: changelog entry cache (3 total): 262144k
[17/Nov/2022:17:22:49.909708217 +0100] - NOTICE - bdb_start_autotune -
cache autosizing: changelog dn cache (3 total): 65536k
[17/Nov/2022:17:22:50.263993498 +0100] - NOTICE - bdb_start_autotune -
total cache size: 1211893760 B;
[17/Nov/2022:17:22:50.333639865 +0100] - ERR - schema-compat-plugin -
scheduled schema-compat-plugin tree scan in about 5 seconds after the
server startup!
[17/Nov/2022:17:22:50.389238294 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=groups,cn=compat,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:51.043292508 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target
cn=computers,cn=compat,dc=hq,dc=spinque,dc=com does not exist
[17/Nov/2022:17:22:51.289250298 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=ng,cn=compat,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:51.707124934 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target ou=sudoers,dc=hq,dc=spinque,dc=com does not
exist
[17/Nov/2022:17:22:52.141269102 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=users,cn=compat,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:52.683089238 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:53.088962531 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:53.508436603 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:53.968874992 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:54.420310634 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:54.999192598 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:55.956089913 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:56.410138348 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:56.849184508 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:57.326422211 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:57.907640062 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=vaults,cn=kra,dc=hq,dc=spinque,dc=com
does not exist
[17/Nov/2022:17:22:58.319864944 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=casigningcert
cert-pki-ca,cn=ca_renewal,cn=ipa,cn=etc,dc=hq,dc=spinque,dc=com does
not exist
[17/Nov/2022:17:22:58.828744743 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=casigningcert
cert-pki-ca,cn=ca_renewal,cn=ipa,cn=etc,dc=hq,dc=spinque,dc=com does
not exist
[17/Nov/2022:17:22:59.370165550 +0100] - WARN - NSACLPlugin -
acl_parse - The ACL target cn=automember rebuild
membership,cn=tasks,cn=config does not exist
[17/Nov/2022:17:22:59.588838582 +0100] - INFO - slapi_vattrspi_regattr
- Because krbPwdPolicyReference is a new registered virtual attribute
, nsslapd-ignore-virtual-attrs was set to 'off'
[17/Nov/2022:17:22:59.745115662 +0100] - ERR - NSMMReplicationPlugin -
bind_and_check_pwp -
agmt="cn=ipa02.hq.spinque.com-to-ipa03.hq.spinque.com
<
http://ipa02.hq.spinque.com-to-ipa03.hq.spinque.com>" (ipa03:389) -
Replication bind with GSSAPI auth failed: LDAP error -1 (Can't contact
LDAP server) ()
[17/Nov/2022:17:22:59.767333919 +0100] - ERR - NSMMReplicationPlugin -
bind_and_check_pwp -
agmt="cn=ipa02.hq.spinque.com-to-ipa03.hq.spinque.com
<
http://ipa02.hq.spinque.com-to-ipa03.hq.spinque.com>" (ipa03:389) -
Replication bind with GSSAPI auth failed: LDAP error -1 (Can't contact
LDAP server) ()
[17/Nov/2022:17:22:59.860445639 +0100] - ERR - schema-compat-plugin -
schema-compat-plugin tree scan will start in about 5 seconds!
[17/Nov/2022:17:23:00.264824712 +0100] - INFO - slapd_daemon - slapd
started. Listening on All Interfaces port 389 for LDAP requests
[17/Nov/2022:17:23:00.921258615 +0100] - INFO - slapd_daemon -
Listening on All Interfaces port 636 for LDAPS requests
[17/Nov/2022:17:23:01.412183755 +0100] - INFO - slapd_daemon -
Listening on /run/slapd-HQ-SPINQUE-COM.socket for LDAPI requests
[17/Nov/2022:17:23:04.807261352 +0100] - ERR - schema-compat-plugin -
warning: no entries set up under cn=computers,
cn=compat,dc=hq,dc=spinque,dc=com
Two things to notice about this last output:
- bind_and_check_pwp -
agmt="cn=ipa02.hq.spinque.com-to-ipa03.hq.spinque.com
<
http://ipa02.hq.spinque.com-to-ipa03.hq.spinque.com>" (ipa03:389) is
not surprising, because ipa03 no longer exists for quite some time. I
thought I had removed it cleanly, but apparently there are still some
reminders. I don't know how serious of a problem this can be, nor how
to remove these traces.
You still have a replication agreement, and until its
removed you will
keep seeing these messages. However it's not related to this issue though.
- sometimes, but not always, this log also shows:
ERR - bdb_version_write - Could not open file
"/dev/shm/slapd-HQ-SPINQUE-COM/DBVERSION" for writing Netscape
Portable Runtime -5950 (File not found.)
This might happen after a system reboot. It should be safe to ignore as
long as the server still starts :)
So looking at the error log it looks like the server is started. Schema
compat plugin is doing its initialization which is very resource
intensive, but the server should still be working.
Try doing a ldapsearch just to see if it's responding:
ldapsearch -H ldap://localhost:389 -b "" -s base -D "cn=directory
manager" -W
Mark