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@HQ-SPINQUE-COM.service
']
ipa: DEBUG: Process finished, return code=0
ipa: DEBUG: Starting external process
ipa: DEBUG: args=['/bin/systemctl', 'is-active',
'dirsrv@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 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"
(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"
(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"
(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.
- 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.)
Afterwards, the file is there. Perhaps just a timing issue?
I don't know what else to look at to see what the problem is.
Thanks for your help, Roberto
_______________________________________________
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-le...@lists.fedorahosted.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.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org
Do not reply to spam, report it:
https://pagure.io/fedora-infrastructure/new_issue
