[Freeipa-users] Re: GSSAPI Authentication Failure and Inaccessible Kerberos Credentials (Replication bind with GSSAPI auth failed)

[Alexander Bokovoy via FreeIPA-users]

On Срд, 02 кас 2024, Jan Wagner via FreeIPA-users wrote:

Thanks for the help!

The directory error logs:
[02/Oct/2024:17:59:28.602977123 +0200] - INFO - main - 389-Directory/2.4.5 
B2024.198.0000 starting up
[02/Oct/2024:17:59:28.603834818 +0200] - INFO - main - Setting the maximum file 
descriptor limit to: 524288
[02/Oct/2024:17:59:28.757212599 +0200] - INFO - PBKDF2_SHA256 - Based on CPU 
performance, chose 2048 rounds
[02/Oct/2024:17:59:28.761796062 +0200] - INFO - 
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[02/Oct/2024:17:59:28.762981918 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr aci
[02/Oct/2024:17:59:28.763954843 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-cachesize
[02/Oct/2024:17:59:28.764851548 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-cachememsize
[02/Oct/2024:17:59:28.765864853 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-readonly
[02/Oct/2024:17:59:28.766752857 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-require-index
[02/Oct/2024:17:59:28.770365686 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-require-internalop-index
[02/Oct/2024:17:59:28.773684553 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-dncachememsize
[02/Oct/2024:17:59:28.774578897 +0200] - INFO - ldbm_instance_config_set - 
instance: userRoot attr nsslapd-directory
[02/Oct/2024:17:59:28.778920839 +0200] - INFO - 
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[02/Oct/2024:17:59:28.780307477 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-cachesize
[02/Oct/2024:17:59:28.782120565 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-cachememsize
[02/Oct/2024:17:59:28.783162621 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-readonly
[02/Oct/2024:17:59:28.786186367 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-require-index
[02/Oct/2024:17:59:28.789426313 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-require-internalop-index
[02/Oct/2024:17:59:28.792723820 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-dncachememsize
[02/Oct/2024:17:59:28.793957866 +0200] - INFO - ldbm_instance_config_set - 
instance: ipaca attr nsslapd-directory
[02/Oct/2024:17:59:28.799717345 +0200] - INFO - 
ldbm_instance_config_cachememsize_set - force a minimal value 512000
[02/Oct/2024:17:59:28.800883081 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-cachesize
[02/Oct/2024:17:59:28.803704736 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-cachememsize
[02/Oct/2024:17:59:28.804882871 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-readonly
[02/Oct/2024:17:59:28.807895887 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-require-index
[02/Oct/2024:17:59:28.811511036 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-require-internalop-index
[02/Oct/2024:17:59:28.812205119 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-dncachememsize
[02/Oct/2024:17:59:28.813153363 +0200] - INFO - ldbm_instance_config_set - 
instance: changelog attr nsslapd-directory
[02/Oct/2024:17:59:28.816725502 +0200] - NOTICE - bdb_start_autotune - found 
7869560k physical memory
[02/Oct/2024:17:59:28.817460326 +0200] - NOTICE - bdb_start_autotune - found 
5419584k available
[02/Oct/2024:17:59:28.818194490 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: db cache: 491847k
[02/Oct/2024:17:59:28.818860603 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: userRoot entry cache (3 total): 458752k
[02/Oct/2024:17:59:28.819647667 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: userRoot dn cache (3 total): 65536k
[02/Oct/2024:17:59:28.820454041 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: ipaca entry cache (3 total): 458752k
[02/Oct/2024:17:59:28.821500706 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: ipaca dn cache (3 total): 65536k
[02/Oct/2024:17:59:28.822282141 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: changelog entry cache (3 total): 458752k
[02/Oct/2024:17:59:28.823039384 +0200] - NOTICE - bdb_start_autotune - cache 
autosizing: changelog dn cache (3 total): 65536k
[02/Oct/2024:17:59:28.823877758 +0200] - NOTICE - bdb_start_autotune - total 
cache size: 2013534208 B;
[02/Oct/2024:17:59:28.833275377 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher AES
[02/Oct/2024:17:59:28.834028980 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.839174626 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher 3DES
[02/Oct/2024:17:59:28.839989300 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.840775824 +0200] - ERR - attrcrypt_init - All prepared 
ciphers are not available. Please disable attribute encryption.
[02/Oct/2024:17:59:28.849378938 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher AES
[02/Oct/2024:17:59:28.850120481 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.855340159 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher 3DES
[02/Oct/2024:17:59:28.856086832 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.856875866 +0200] - ERR - attrcrypt_init - All prepared 
ciphers are not available. Please disable attribute encryption.
[02/Oct/2024:17:59:28.865336600 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher AES
[02/Oct/2024:17:59:28.865856502 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.871143999 +0200] - ERR - attrcrypt_unwrap_key - Failed to 
unwrap key for cipher 3DES
[02/Oct/2024:17:59:28.871935833 +0200] - ERR - attrcrypt_cipher_init - 
Symmetric key failed to unwrap with the private key; Cert might have been 
renewed since the key is wrapped.  To recover the encrypted contents, keep the 
wrapped symmetric key value.
[02/Oct/2024:17:59:28.872698347 +0200] - ERR - attrcrypt_init - All prepared 
ciphers are not available. Please disable attribute encryption.
[02/Oct/2024:17:59:28.876139944 +0200] - ERR - schema-compat-plugin - scheduled 
schema-compat-plugin tree scan in about 5 seconds after the server startup!
[02/Oct/2024:17:59:28.882424687 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=dns,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.883226651 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=dns,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.884134405 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=keys,cn=sec,cn=dns,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.884854119 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=dns,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.885587583 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=dns,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.886353897 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=groups,cn=compat,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.887069180 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=computers,cn=compat,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.887933154 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=ng,cn=compat,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.888835939 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target ou=sudoers,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.889665023 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=users,cn=compat,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.890518288 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.891389432 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.892263517 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.893110060 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.893960015 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.894869610 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.896913830 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.897840905 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.898707439 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.899594584 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.900412688 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=vaults,cn=kra,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.906548959 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=casigningcert 
cert-pki-ca,cn=ca_renewal,cn=ipa,cn=etc,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.907416734 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=casigningcert 
cert-pki-ca,cn=ca_renewal,cn=ipa,cn=etc,dc=example,dc=com does not exist
[02/Oct/2024:17:59:28.968084072 +0200] - WARN - NSACLPlugin - acl_parse - The 
ACL target cn=automember rebuild membership,cn=tasks,cn=config does not exist
[02/Oct/2024:17:59:28.971970842 +0200] - INFO - slapi_vattrspi_regattr - 
Because krbPwdPolicyReference is a new registered virtual attribute , 
nsslapd-ignore-virtual-attrs was set to 'off'
[02/Oct/2024:17:59:28.973265389 +0200] - ERR - cos-plugin - cos_dn_defs_cb - 
Skipping CoS Definition cn=Password Policy,cn=accounts,dc=example,dc=com--no 
CoS Templates found, which should be added before the CoS Definition.
[02/Oct/2024:17:59:29.001093670 +0200] - ERR - schema-compat-plugin - 
schema-compat-plugin tree scan will start in about 5 seconds!
[02/Oct/2024:17:59:29.004581568 +0200] - INFO - 
validate_num_config_reservedescriptors - reserve descriptors changed from 64 to 
239
[02/Oct/2024:17:59:29.005342833 +0200] - INFO - connection_table_new - Number 
of connection sub-tables 1, each containing 63761 slots.
[02/Oct/2024:17:59:29.039105944 +0200] - INFO - slapd_daemon - slapd started.  
Listening on All Interfaces port 389 for LDAP requests
[02/Oct/2024:17:59:29.039831128 +0200] - INFO - slapd_daemon - Listening on All 
Interfaces port 636 for LDAPS requests
[02/Oct/2024:17:59:29.040547442 +0200] - INFO - slapd_daemon - Listening on 
/run/slapd-EXAMPLE-COM.socket for LDAPI requests
[02/Oct/2024:17:59:34.064575010 +0200] - ERR - schema-compat-plugin - warning: 
no entries set up under ou=sudoers,dc=example,dc=com
[02/Oct/2024:17:59:34.065597825 +0200] - ERR - schema-compat-plugin - warning: 
no entries set up under cn=ng, cn=compat,dc=example,dc=com
[02/Oct/2024:17:59:34.421255856 +0200] - ERR - schema-compat-plugin - warning: 
no entries set up under cn=computers, cn=compat,dc=example,dc=com
[02/Oct/2024:17:59:34.422227820 +0200] - ERR - schema-compat-plugin - Finished 
plugin initialization.

The directory security logs are full of "Bad Ber Tag".

In the directory access log, there are some succesfull searches (regarding 
kerberos ticket, I assume from localhost) and some GSSAPI errors:
[02/Oct/2024:18:59:19.893133208 +0200] conn=511 op=1 BIND dn="" method=sasl 
version=3 mech=GSSAPI
[02/Oct/2024:18:59:19.894177503 +0200] conn=511 op=1 RESULT err=49 tag=97 
nentries=0 wtime=0.000032210 optime=0.001046625 etime=0.001077535 - SASL(-1): 
generic failure: GSSAPI Error: No credentials were supplied, or the credentials 
were unavailable or inaccessible (Permission denied)
[02/Oct/2024:18:59:19.988382631 +0200] conn=511 op=2 UNBIND


It seems to request tickets very often (multiple times per minute):
Oct 02 18:09:15 replica1.example.com krb5kdc[3234564](info): AS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: 
NEEDED_PREAUTH: host/replica1.example....@example.com for 
krbtgt/example....@example.com, Additional pre-authentication required
Oct 02 18:09:15 replica1.example.com krb5kdc[3234564](info): AS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: ISSUE: 
authtime 1727885355, etypes {rep=aes256-cts-hmac-sha384-192(20), 
tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)}, 
host/replica1.example....@example.com for krbtgt/example....@example.com
Oct 02 18:09:15 replica1.example.com krb5kdc[3234562](info): TGS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: ISSUE: 
authtime 1727885355, etypes {rep=aes256-cts-hmac-sha384-192(20), 
tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha384-192(20)}, 
host/replica1.example....@example.com for ldap/replica1.example....@example.com
Oct 02 18:09:15 replica1.example.com krb5kdc[3234564](info): AS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: 
NEEDED_PREAUTH: host/replica1.example....@example.com for 
krbtgt/example....@example.com, Additional pre-authentication required
Oct 02 18:09:15 replica1.example.com krb5kdc[3234564](info): AS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: ISSUE: 
authtime 1727885355, etypes {rep=aes256-cts-hmac-sha384-192(20), 
tkt=aes256-cts-hmac-sha384-192(20), ses=aes256-cts-hmac-sha384-192(20)}, 
host/replica1.example....@example.com for krbtgt/example....@example.com
Oct 02 18:09:15 replica1.example.com krb5kdc[3234564](info): TGS_REQ (4 etypes 
{aes256-cts-hmac-sha384-192(20), aes128-cts-hmac-sha256-128(19), 
aes256-cts-hmac-sha1-96(18), aes128-cts-hmac-sha1-96(17)}) 1.2.3.4: ISSUE: 
authtime 1727885355, etypes {rep=aes256-cts-hmac-sha384-192(20), 
tkt=aes256-cts-hmac-sha1-96(18), ses=aes256-cts-hmac-sha384-192(20)}, 
host/replica1.example....@example.com for ldap/replica1.example....@example.com

I believe this should not be the case, the ticket should be requested once and 
used as long as it is valid, no?

These host/... -> ldap/... are requests from SSSD on the replica1. They
are not related to ldap/.. service own operations. But the fact you see
multitude of these requests here is a side-effect of LDAP server not
completing the authentication with the client (in this case LDAP client
is that SSSD on the replica1).

LDAP server does not need to request a Kerberos ticket to authenticate
incoming connections. It needs access to its own keytab. It will only
request a ticket when it becomes a client itself -- that happens when it
initiates replication to other IPA replica.

The 'permission denied' part is definitely telling us that LDAP server
cannot access its own keytab.

--
/ Alexander Bokovoy
Sr. Principal Software Engineer
Security / Identity Management Engineering
Red Hat Limited, Finland

--
_______________________________________________
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