Hi Roberto,

On 11/17/22 11:36 AM, Roberto Cornacchia via FreeIPA-users wrote:
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.
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


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-leave@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
-- 
Directory Server Development Team