freeipa

#9251 [Tracker] nightly failure: server installation failed with setup_dns, setup_kra setup_adtrust
Closed: duplicate by frenaud. Opened by amore.

Closed: duplicate
Reopen Issue

FreeIPA nightly tests fails to install server with dns, kra and adtrust.
report.
Steps to Reproduce
Install server with dns, kra and adtrust.
Actual behavior

DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd39:transport.py:557 Configuration of client side components failed!
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd39:transport.py:557 The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd39:transport.py:217 Exit code: 1

Failure observed in testing_master_testing_selinux
Expected behavior
Server install should succeed.
Version/Release/Distribution
The full package list is available here.
Logs can be found here

Metadata Update from @amore:
- Issue tagged with: test-failure, tests, tracker

Installed packages

389-ds-base-2.1.5-1.fc36.x86_64
krb5-server-1.19.2-11.fc36.x86_64
freeipa-server from master branch (https://github.com/freeipa-pr-ci2/freeipa/tree/9d9d925b14dbf627546c51c47f6d4e7827645610)

Initial investigations

The failure looks random as other tests in the same nightly run completed the installation with no issue.

The test fails during the server installation:

ipa-server-install -n ipa.test -r IPA.TEST -p Secret.123 -a Secret.123 --domain-level=1 --dirsrv-config-file /ipatests/ipatests_dse.ldif -U --setup-dns --forwarder 192.168.122.1 --auto-reverse --setup-kra --setup-adtrust

ipaserver-install.log points to an error in the step calling the client installation:

2022-09-28T17:33:34Z DEBUG The ipa-server-install command failed, exception: ScriptError: Configuration of client side components failed!

ipaclient-install.log fails with a kerberos issue:

2022-09-28T17:33:34Z DEBUG The ipa-client-install command failed, exception: CCacheError: did not receive Kerberos credentials
2022-09-28T17:33:34Z ERROR did not receive Kerberos credentials

According to the journal, krb5kdc dumped core a few seconds earlier:

Sep 28 17:32:59 master.ipa.test systemd-coredump[23584]: Process 21221 (krb5kdc) of user 0 dumped core.
...
Module libcrypt.so.2 with build-id 9924d3a82ca8fa6b94bc574a6520bcf84ccf831f
                                                         Stack trace of thread 21221:
                                                         #0  0x00007f5fba4c0c4c __pthread_kill_implementation (libc.so.6 + 0x8ec4c)
                                                         #1  0x00007f5fba4709c6 raise (libc.so.6 + 0x3e9c6)
                                                         #2  0x00007f5fba45a7f4 abort (libc.so.6 + 0x287f4)
                                                         #3  0x00007f5fba45a71b __assert_fail_base.cold (libc.so.6 + 0x2871b)
                                                         #4  0x00007f5fba469576 __assert_fail (libc.so.6 + 0x37576)
                                                         #5  0x00007f5fb954f828 ldap_get_entry_controls (libldap.so.2 + 0x2d828)
                                                         #6  0x00007f5fb9bc0773 ipadb_ldap_deref_results (ipadb.so + 0x7773)
                                                         #7  0x00007f5fb9bc77a8 ipadb_get_pac (ipadb.so + 0xe7a8)
                                                         #8  0x00007f5fb9bcc0fe ipadb_sign_authdata (ipadb.so + 0x130fe)
                                                         #9  0x0000564d0b17aa95 handle_authdata (krb5kdc + 0x1ba95)
                                                         #10 0x0000564d0b16f98e finish_process_as_req.lto_priv.0 (krb5kdc + 0x1098e)
                                                         #11 0x00007f5fb656eadc spake_verify (spake.so + 0x9adc)
                                                         #12 0x0000564d0b16c141 next_padata (krb5kdc + 0xd141)
                                                         #13 0x0000564d0b175915 dispatch (krb5kdc + 0x16915)
                                                         #14 0x0000564d0b178f7c process_tcp_connection_read (krb5kdc + 0x19f7c)
                                                         #15 0x00007f5fba6387cc verto_fire (libverto.so.1 + 0x47cc)
                                                         #16 0x00007f5fb65c5d0b ev_invoke_pending (libev.so.4 + 0x5d0b)
                                                         #17 0x00007f5fb65c98e8 ev_run (libev.so.4 + 0x98e8)
                                                         #18 0x0000564d0b168d05 main (krb5kdc + 0x9d05)
                                                         #19 0x00007f5fba45b550 __libc_start_call_main (libc.so.6 + 0x29550)
                                                         #20 0x00007f5fba45b609 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x29609)
                                                         #21 0x0000564d0b1693c5 _start (krb5kdc + 0xa3c5)
                                                         ELF object binary architecture: AMD x86-64

We need to analyze the coredump and open an issue against the right component but it seems located in ipa-kdb plugin.

Looks like one more case of LDAP instance in kdb not being valid as ldap_get_entry_controls performs assert checks in the beginning:

        assert( ld != NULL );
        assert( LDAP_VALID( ld ) );
        assert( entry != NULL );
        assert( sctrls != NULL );

The only static function called from ipadb_get_pac() that might lead to use of ipadb_ldap_deref_results() is ipadb_fill_info3(): 

    lentry = ldap_first_entry(ipactx->lcontext, results);
    if (!lentry) {
        kerr = ENOENT;
        goto done;
    }
    /* == Fill Info3 == */
    kerr = ipadb_fill_info3(ipactx, lentry, flags, tmpctx, authtime,
                            &pac_info.logon_info.info->info3);
    if (kerr) {
        goto done;
    }

and before ipadb_fill_info3() calls into ipadb_ldap_deref_results(), we already use ipactx->lcontext or lentry so they are guaranteed to be non-NULL, unless some other code resets ipactx->lcontext like we saw in past.

From https://pagure.io/freeipa/issue/9253, there is an indication that ipactx->lcontext was NULL when passing it to ipadb_ldap_deref_results.

The segfaults are clustered together at times for the KDC.

Mon 2022-10-03 21:22:42 CDT 1014990 0 0 6 error /usr/sbin/krb5kdc
Mon 2022-10-03 22:31:05 CDT 1589292 0 0 6 none /usr/sbin/krb5kdc
Tue 2022-10-04 05:30:56 CDT 1594328 0 0 6 none /usr/sbin/krb5kdc
Tue 2022-10-04 05:32:20 CDT 1626262 0 0 6 none /usr/sbin/krb5kdc
Tue 2022-10-04 05:35:44 CDT 1626363 0 0 6 none /usr/sbin/krb5kdc

I'm not sure that means anything but there it is. [?] Not sure.

It's still segfaulting consistently in the same place. 

#3  0x00007f79a038aa76 in __GI___assert_fail (assertion=assertion@entry=0x7f7991b87228 "ld != NULL", file=file@entry=0x7f7991b848bc "getentry.c", line=line@entry=89,
    function=function@entry=0x7f7991b848e0 <__PRETTY_FUNCTION__.8960> "ldap_get_entry_controls") at assert.c:101
#4  0x00007f7991b66518 in ldap_get_entry_controls (ld=ld@entry=0x0, entry=entry@entry=0x5654aeda4fc0, sctrls=sctrls@entry=0x7ffc6ff10710) at getentry.c:89
#5  0x00007f7992ad6bf7 in ipadb_ldap_deref_results (lcontext=0x0, le=le@entry=0x5654aeda4fc0, results=results@entry=0x7ffc6ff107c0) at ipa_kdb_common.c:572
#6  0x00007f7992adc38b in ipadb_fill_info3 (info3=0x5654aeaa5cb0, authtime=1664849966, memctx=0x5654aeeb5280, flags=112, lentry=0x5654aeda4fc0, ipactx=0x5654ae61b890) at ipa_kdb_mspac.c:669

If you can provide the coredump that would be awesome. What happens is that we get to ipadb_fill_info3() with ipactx->lcontext being not NULL, pass it to some other libldap calls and then pass NULL (e.g. ipactx->lcontext is NULL here) to ipadb_ldap_deref_results().

Most of the calls prior to ipadb_ldap_deref_results() call are only operating on the ldap attributes and their values in the lentry. There is one place where we might reset ipadb->lcontext: a call to is_master_host() which calls into ipadb_simple_search(). But this only happens for a host or a service principal and from the backtrace it is unclear whether we are dealing with it.

@demigod thank you for the coredump. I can confirm this is the case as in my previous comment -- the failure is in processing PAC for the host principal offqdn=c444.$domain,cn=computers,cn=accounts,dc=$BASEDN, so we must have got into the is_master_host(). This narrows the search path down.

Sadly, I cannot get the backtrace out of the coredump. Something simply does not fit well in my CentOS 8 Stream images, even though the same packages get installed. I can peek through the direct memory references, though, and decode structures in the memory. This should be enough to investigate more.

@abbra Here's the full backtrace out of the coredump file. If there's anything else you need just let me know.

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f79a037cdb5 in __GI_abort () at abort.c:79
#2  0x00007f79a037cc89 in __assert_fail_base (fmt=0x7f79a04e5698 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7f7991b87228 "ld != NULL", file=0x7f7991b848bc "getentry.c", line=89,
    function=<optimized out>) at assert.c:92
#3  0x00007f79a038aa76 in __GI___assert_fail (assertion=assertion@entry=0x7f7991b87228 "ld != NULL", file=file@entry=0x7f7991b848bc "getentry.c", line=line@entry=89,
    function=function@entry=0x7f7991b848e0 <__PRETTY_FUNCTION__.8960> "ldap_get_entry_controls") at assert.c:101
#4  0x00007f7991b66518 in ldap_get_entry_controls (ld=ld@entry=0x0, entry=entry@entry=0x5654aeda4fc0, sctrls=sctrls@entry=0x7ffc6ff10710) at getentry.c:89
#5  0x00007f7992ad6bf7 in ipadb_ldap_deref_results (lcontext=0x0, le=le@entry=0x5654aeda4fc0, results=results@entry=0x7ffc6ff107c0) at ipa_kdb_common.c:572
#6  0x00007f7992adc38b in ipadb_fill_info3 (info3=0x5654aeaa5cb0, authtime=1664849966, memctx=0x5654aeeb5280, flags=112, lentry=0x5654aeda4fc0, ipactx=0x5654ae61b890) at ipa_kdb_mspac.c:669
#7  ipadb_get_pac (kcontext=kcontext@entry=0x5654ae6decc0, client=0x5654aeb56be0, flags=112, authtime=1664849966, pac=0x7ffc6ff10a10) at ipa_kdb_mspac.c:868
#8  0x00007f7992ade784 in ipadb_sign_authdata (context=0x5654ae6decc0, flags=112, client_princ=<optimized out>, client=0x5654aeb56be0, server=0x5654aeaefd30, krbtgt=0x5654aeaefd30, client_key=0x5654aeeaa810,
    server_key=0x5654aeeaa7f8, krbtgt_key=0x5654aeeaa7e0, session_key=0x5654aeeaa910, authtime=1664849966, tgt_auth_data=0x0, signed_auth_data=0x7ffc6ff10c70) at ipa_kdb_mspac.c:2285
#9  0x00005654acd8fe71 in fetch_kdb_authdata (req=0x5654aed3fd20, req=0x5654aed3fd20, auth_indicators=0x5654aeeaa970, enc_tkt_reply=0x5654aeeaa708, enc_tkt_req=0x0, ad_info=0x0, altcprinc=0x0,
    local_tgt_key=0x5654aeeaa7e0, header_key=0x0, server_key=0x5654aeeaa7f8, client_key=0x5654aeeaa810, local_tgt=0x5654aeaefd30, header_server=0x0, server=0x5654aeaefd30, client=0x5654aeb56be0, flags=112,
    context=0x5654ae6decc0) at kdc_authdata.c:366
#10 handle_authdata (context=0x5654ae6decc0, flags=112, client=0x5654aeb56be0, server=0x5654aeaefd30, subject_server=subject_server@entry=0x0, local_tgt=0x5654aeaefd30, local_tgt_key=0x5654aeeaa7e0,
    client_key=0x5654aeeaa810, server_key=0x5654aeeaa7f8, subject_key=0x0, req_pkt=0x5654aeb7bb60, req=0x5654aed3fd20, altcprinc=0x0, ad_info=0x0, enc_tkt_req=0x0, auth_indicators=0x5654aeeaa970,
    enc_tkt_reply=0x5654aeeaa708) at kdc_authdata.c:854
#11 0x00005654acd81084 in finish_process_as_req (state=0x5654aeeaa6d0, errcode=<optimized out>) at do_as_req.c:284
#12 0x00005654acd8a556 in finish_check_padata (state=0x5654aed498c0, code=<optimized out>) at kdc_preauth.c:1197
#13 0x00005654acd8ce74 in enc_ts_verify (context=0x5654ae6decc0, req_pkt=<optimized out>, request=<optimized out>, enc_tkt_reply=0x5654aeeaa708, pa=<optimized out>, cb=<optimized out>, rock=0x5654aeeaa858,
    moddata=0x0, respond=0x5654acd8b0d0 <finish_verify_padata>, arg=0x5654aed498c0) at kdc_preauth_encts.c:118
#14 0x00005654acd8b04f in next_padata (state=<optimized out>) at kdc_preauth.c:1308
#15 0x00005654acd81f77 in process_as_req (request=<optimized out>, req_pkt=req_pkt@entry=0x5654aeb7bb60, local_addr=local_addr@entry=0x5654aeb7bb48, remote_addr=remote_addr@entry=0x5654aeb1f970,
    kdc_active_realm=0x5654ae61bb50, vctx=vctx@entry=0x5654ae63af30, respond=0x5654acd802a0 <finish_dispatch_cache>, arg=0x5654aed77ba0) at do_as_req.c:797
#16 0x00005654acd805b8 in dispatch (cb=0x5654acf9e140 <shandle>, local_addr=local_addr@entry=0x5654aeb7bb48, remote_addr=remote_addr@entry=0x5654aeb1f970, pkt=pkt@entry=0x5654aeb7bb60, is_tcp=is_tcp@entry=1,
    vctx=vctx@entry=0x5654ae63af30, respond=0x5654acd93850 <process_tcp_response>, arg=0x5654aeb7bab0) at dispatch.c:201
#17 0x00005654acd95f6d in process_tcp_connection_read (ctx=0x5654ae63af30, ev=<optimized out>) at net-server.c:1359
#18 0x00007f79a07235ec in verto_fire () from /lib64/libverto.so.1
#19 0x00007f7989b72ff1 in event_process_active_single_queue () from /lib64/libevent-2.1.so.6
#20 0x00007f7989b73787 in event_base_loop () from /lib64/libevent-2.1.so.6
#21 0x00005654acd7f2e9 in main (argc=5, argv=0x7ffc6ff114d8) at main.c:1064

Thanks. I have a preliminary fix but I wonder if you have any directory server and krb5kdc logs from around the time when crash happened? I want to see if there are any signs of a broken connection.

So far 5 days have past since the last /usr/sbin/krb5kdc crash.

Was this turned into a change request for another plugin?

@demigod I am currently on vacation (due to school holidays and a need to handle not just code..), this will have to wait some time.

@abbra I have a work around in place. I restart the KDC with 'ipactl start' if it goes down. I'm sure that will hold until later.

This issue is likely a duplicate of https://pagure.io/freeipa/issue/9422 which is already fixed.
Feel free to re-open with additional logs if that's not the case.

Metadata Update from @frenaud:
- Issue close_status updated to: duplicate
- Issue status updated to: Closed (was: Open)
Metadata
None

test-failure tests tracker

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.