freeipa

#9300 ipa sudden failure
Closed: insufficientinfo by rcritten. Opened by mshash.

Closed: insufficientinfo
Reopen Issue

Issue

Hi Team,
we're using FreeIPA 4.6.8 on CentOS 7.9 to secure an Hadoop cluster.
But, regularly, we have FreeIPA that is having trouble: We lost SLAPD.
Then production jobs are failing.

Here the logs we have :

/var/log/dirsrv/slapd-DATA-GPS/errors :

[10/Dec/2022:02:07:18.716900616 +0100] - ERR - libdb - BDB2520 /var/lib/dirsrv/slapd-DATA-GPS/db/log.0000009532: log file unreadable: Timer expired
[10/Dec/2022:02:07:24.713406478 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:07:25.712244912 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:07:25.721098652 +0100] - ERR - libdb - BDB0061 PANIC: Timer expired
[10/Dec/2022:02:07:26.695199448 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:07:49.714916490 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:07:51.691315167 +0100] - ERR - NSMMReplicationPlugin - changelog program - _cl5TrimFile - Failed to begin transaction; db error - -30973 BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
[10/Dec/2022:02:08:04.697071614 +0100] - CRIT - deadlock_threadmain - Serious Error---Failed in deadlock detect (aborted at 0x0), err=-30973 (BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery)
[10/Dec/2022:02:08:11.716912038 +0100] - ERR - _entryrdn_get_elem - Failed to position cursor at the key: C2: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:13.714014929 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:14.690723999 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:14.704784746 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:14.716276504 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:15.693782836 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:15.704032836 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:15.716094943 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:16.691143768 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:16.698865243 +0100] - ERR - entryrdn_index_read_ext - Failed to close cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:16.712038126 +0100] - ERR - entryrdn_index_read_ext - Failed to make a cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:16.723118384 +0100] - ERR - dn2entry_ext - Failed to get id for uid=admin,cn=users,cn=accounts,dc=data,dc=gps from entryrdn index (-30973)
[10/Dec/2022:02:08:17.695288503 +0100] - ERR - entryrdn_index_read_ext - Failed to make a cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:17.709081100 +0100] - ERR - dn2entry_ext - Failed to get id for uid=admin,cn=users,cn=accounts,dc=data,dc=gps from entryrdn index (-30973)
[10/Dec/2022:02:08:18.691609144 +0100] - ERR - entryrdn_index_read_ext - Failed to make a cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:18.703574454 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:18.718376566 +0100] - ERR - dn2entry_ext - Failed to get id for uid=admin,cn=users,cn=accounts,dc=data,dc=gps from entryrdn index (-30973)
[10/Dec/2022:02:08:19.701335563 +0100] - ERR - entryrdn_index_read_ext - Failed to make a cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:20.689598420 +0100] - ERR - dn2entry_ext - Failed to get id for uid=admin,cn=users,cn=accounts,dc=data,dc=gps from entryrdn index (-30973)
[10/Dec/2022:02:08:20.697340414 +0100] - ERR - NSMMReplicationPlugin - changelog program - _cl5TrimFile - Failed to begin transaction; db error - -30973 BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery
[10/Dec/2022:02:08:20.713649234 +0100] - ERR - dn2entry_ext - Failed to get id for uid=admin,cn=users,cn=accounts,dc=data,dc=gps from entryrdn index (-30973)
[10/Dec/2022:02:08:21.699048233 +0100] - ERR - entryrdn_index_read_ext - Failed to close cursor: BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery(-30973)
[10/Dec/2022:02:08:22.704354449 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:23.689845685 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:23.700780870 +0100] - ERR - libdb - BDB0060 PANIC: fatal region error detected; run recovery
[10/Dec/2022:02:08:24.713601675 +0100] - CRIT - deadlock_threadmain - Serious Error---Failed in deadlock detect (aborted at 0x0), err=-30973 (BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery)

grep -i ipa /var/log/messages | grep "Dec 10 02"

Dec 10 02:00:04 xxxxxx-vkb001 ns-slapd: [10/Dec/2022:02:00:04.911094133 +0100] - INFO - task_export_thread - Beginning export of 'ipaca'
Dec 10 02:00:16 xxxxxx-vkb001 ns-slapd: [10/Dec/2022:02:00:13.733393357 +0100] - INFO - ldbm_back_ldbm2ldif - export ipaca: Processed 167 entries (100%).
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: ipa-dnskeysyncd: ERROR syncrepl_poll: LDAP error ({'desc': "Can't contact LDAP server"})
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: Traceback (most recent call last):
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: File "/usr/libexec/ipa/ipa-dnskeysyncd", line 116, in
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 348, in syncrepl_poll
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: add_intermediates=1, add_ctrls=1, all = 0
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 476, in result4
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 99, in _ldap_call
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: result = func(args,*kwargs)
Dec 10 02:09:25 xxxxxx-vkb001 ipa-dnskeysyncd: SERVER_DOWN: {'desc': "Can't contact LDAP server"}
Dec 10 02:09:25 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service: main process exited, code=exited, status=1/FAILURE
Dec 10 02:09:25 xxxxxx-vkb001 systemd: Unit ipa-dnskeysyncd.service entered failed state.
Dec 10 02:09:25 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service failed.
Dec 10 02:10:25 xxxxxx-vkb001 named-pkcs11[28447]: Failed to get initial credentials (TGT) using principal 'DNS/xxxxxx-vkb001.data.gps' and keytab 'FILE:/etc/named.keytab' (Generic error (see e-text))
Dec 10 02:10:25 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service holdoff time over, scheduling restart.
Dec 10 02:10:25 xxxxxx-vkb001 systemd: Stopped IPA key daemon.
Dec 10 02:10:25 xxxxxx-vkb001 systemd: Started IPA key daemon.
Dec 10 02:10:28 xxxxxx-vkb001 ipa-dnskeysyncd: ipa-dnskeysyncd: CRITICAL Kerberos authentication failed: Major (851968): Unspecified GSS failure. Minor code may provide more information, Minor (2529638972): Generic error (see e-text)
Dec 10 02:10:28 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service: main process exited, code=exited, status=1/FAILURE
Dec 10 02:10:28 xxxxxx-vkb001 systemd: Unit ipa-dnskeysyncd.service entered failed state.
Dec 10 02:10:28 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service failed.
Dec 10 02:11:25 xxxxxx-vkb001 named-pkcs11[28447]: Failed to get initial credentials (TGT) using principal 'DNS/xxxxxx-vkb001.data.gps' and keytab 'FILE:/etc/named.keytab' (Generic error (see e-text))
Dec 10 02:11:28 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service holdoff time over, scheduling restart.
Dec 10 02:11:28 xxxxxx-vkb001 systemd: Stopped IPA key daemon.
Dec 10 02:11:28 xxxxxx-vkb001 systemd: Started IPA key daemon.
Dec 10 02:11:30 xxxxxx-vkb001 ipa-dnskeysyncd: ipa-dnskeysyncd: CRITICAL Kerberos authentication failed: Major (851968): Unspecified GSS failure. Minor code may provide more information, Minor (2529638972): Generic error (see e-text)
Dec 10 02:11:30 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service: main process exited, code=exited, status=1/FAILURE
Dec 10 02:11:30 xxxxxx-vkb001 systemd: Unit ipa-dnskeysyncd.service entered failed state.
Dec 10 02:11:30 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service failed.
Dec 10 02:12:25 xxxxxx-vkb001 named-pkcs11[28447]: Failed to get initial credentials (TGT) using principal 'DNS/xxxxxx-vkb001.data.gps' and keytab 'FILE:/etc/named.keytab' (Generic error (see e-text))
Dec 10 02:12:30 xxxxxx-vkb001 systemd: ipa-dnskeysyncd.service holdoff time over, scheduling restart.
Dec 10 02:12:30 xxxxxx-vkb001 systemd: Stopped IPA key daemon.
Dec 10 02:12:30 xxxxxx-vkb001 systemd: Started IPA key daemon.

=>
vkb001-slapd :: Serious Error---Failed in deadlock detect (aborted at 0x0), err=-30973 (BDB0087 DB_RUNRECOVERY: Fatal error, run database recovery)

Do you have already encountered this problem ?

Thanks in advance for your support.
Regards.

Steps to Reproduce

I don't have a clue

Actual behavior

this happened every now and then with no defined pattern

Expected behavior

shouldn't happen.

Version/Release/Distribution

$ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server

package freeipa-server is not installed
package freeipa-client is not installed
ipa-server-4.6.8-5.el7.centos.6.x86_64
ipa-client-4.6.8-5.el7.centos.6.x86_64
389-ds-base-1.3.10.2-12.el7_9.x86_64
pki-ca-10.5.18-14.el7_9.noarch
krb5-server-1.15.1-50.el7.x86_64

A similar issue was already discussed in https://access.redhat.com/solutions/3098131 and the recommendation was to check if the file system is full or increase nsslapd-dncachememsize cache size.
If it doesn't solve your problem, please open an issue against 389-ds at https://github.com/389ds/389-ds-base/issues/new/choose

The failure "BDB2520 /var/lib/dirsrv/slapd-DATA-GPS/db/log.0000009532: log file unreadable" occurs when the log file exists but the DS process fails to open it (like rights not granted). If it is in middle of production, with 'Timer Expired', I agree it is looking like environment issue (FS full, unmount, ...). Because of the number of txn file (9532), I wonder if a previous admin task (export/import) was interrupted (or DS killed) leaving a TXN uncommitted, that prevent checkpointing to trim the log files and fill the FS.

A similar issue was already discussed in https://access.redhat.com/solutions/3098131 and the recommendation was to check if the file system is full or increase nsslapd-dncachememsize cache size.
If it doesn't solve your problem, please open an issue against 389-ds at https://github.com/389ds/389-ds-base/issues/new/choose

sorry for my ignorance, but how can I increase nsslapd-dncachememsize cache size.

This setting is described in Red Hat Directory Server guide Configuration and schema reference, in this section.
The value is stored in LDAP below cn=database_name,cn=ldbm database,cn=plugins,cn=config, and you can change it with ldapmodify. The following is an example for the userRoot database:

# ldapmodify -x -h localhost -p 389 -D "cn=Directory Manager" -w Secret123  << EOF
dn: cn=userRoot,cn=ldbm database,cn=plugins,cn=config
changetype: modify
replace: nsslapd-dncachememsize
nsslapd-dncachememsize: 67108864
EOF

is the DN should be the same or it is different from environment to another.

is the DN should be the same or it is different from environment to another.

The RDN part can differ, depending on the database you want to configure:
cn=userRoot,cn=ldbm database,cn=plugins,cn=config for the DB containing the users, groups etc...
cn=ipaca,cn=ldbm database,cn=plugins,cn=config for the DB used by the Certificate Server

We seem to have lost traction on this. Closing.

Metadata Update from @rcritten:
- Issue close_status updated to: insufficientinfo
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.