Bug 35667

Summary:	FreeIPA installation fails
Product:	Sisyphus	Reporter:	Stanislav Levin <slev>
Component:	libkrb5	Assignee:	Ivan A. Melnikov <iv>
Status:	CLOSED FIXED	QA Contact:	qa-sisyphus
Severity:	major
Priority:	P3	CC:	iv, shaba
Version:	unstable
Hardware:	all
OS:	Linux

Description

Stanislav Levin 2018-11-29 10:08:26 MSK

Symptom: 389-ds crashes on FreeIPA installation:
```
Done configuring DNS key synchronization service (ipa-dnskeysyncd).
Restarting ipa-dnskeysyncd
Restarting named
Named service failed to start (CalledProcessError(Command ['/sbin/systemctl', 'restart', 'bind.service'] returned non-zero exit status 1: 'Job for bind.service failed because the control process exited with error code.\nSee "systemctl status bind.service" and "journalctl -xe" for details.\n'))
named service failed to start
```

Name debug log:
```
29-Nov-2018 09:50:34.015 trying to establish LDAP connection to ldapi://%2fvar%2frun%2fslapd-IPASL-IPATEST.socket
29-Nov-2018 09:50:34.015 Using default keytab file name: FILE:/etc/named.keytab
29-Nov-2018 09:50:34.015 Credentials are not present in cache (Matching credential not found)
29-Nov-2018 09:50:34.015 Attempting to acquire new Kerberos credentials
Missing separate debuginfo for /usr/lib64/krb5/plugins/libkrb5/sssd_krb5_locator_plugin.so
Try to install the hash file /usr/lib/debug/.build-id/70/8f27e90579e8a1bb44d9ada32e82f61438f694.debug
29-Nov-2018 09:50:34.047 trying interactive bind using 'GSSAPI' mechanism
29-Nov-2018 09:50:34.047 doing interactive bind
29-Nov-2018 09:50:34.047 got request for SASL_CB_USER
k5_mutex_lock: Received error 22 (Invalid argument)
named: ../../../include/k5-thread.h:376: k5_mutex_lock: Assertion `r == 0' failed.

Thread 2 "isc-worker0000" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff4e53700 (LWP 14531)]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
```

bt
```
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff60ae371 in __GI_abort () at abort.c:79
#2  0x00007ffff60a5b1a in __assert_fail_base (
    fmt=0x7ffff61f8e88 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x7ffff1429da5 "r == 0", 
    file=file@entry=0x7ffff1429d88 "../../../include/k5-thread.h", line=line@entry=376, 
    function=function@entry=0x7ffff1429e70 <__PRETTY_FUNCTION__.5551> "k5_mutex_lock")
    at assert.c:92
#3  0x00007ffff60a5b92 in __GI___assert_fail (
    assertion=assertion@entry=0x7ffff1429da5 "r == 0", 
    file=file@entry=0x7ffff1429d88 "../../../include/k5-thread.h", line=line@entry=376, 
    function=function@entry=0x7ffff1429e70 <__PRETTY_FUNCTION__.5551> "k5_mutex_lock")
    at assert.c:101
#4  0x00007ffff13cd143 in k5_mutex_lock (m=0x7fffec36e358) at ../../../include/k5-thread.h:376
#5  0x00007ffff13d386f in k5_mutex_lock (m=0x7fffec36e358) at /usr/include/bits/stdio2.h:97
#6  k5_cc_mutex_lock (context=context@entry=0x7fffec3715c0, m=m@entry=0x7fffec36e358)
    at ccbase.c:460
#7  0x00007ffff13db5d8 in krb5_mcc_close (context=0x7fffec3715c0, id=<optimized out>)
    at cc_memory.c:212
#8  0x00007ffff13d647b in realm_choose (context=0x7fffec3715c0, data=<optimized out>, 
    server=0x7fffec371370, cache_out=0x7ffff4e503e0, princ_out=0x7ffff4e503f8)
    at ccselect_realm.c:69
#9  0x00007ffff13d579e in krb5_cc_select (context=context@entry=0x7fffec3715c0, 
    server=0x7fffec371370, cache_out=cache_out@entry=0x7fffec371a78, 
    princ_out=princ_out@entry=0x7ffff4e50448) at ccselect.c:171
#10 0x00007fffea3e7edb in kg_cred_resolve (minor_status=minor_status@entry=0x7ffff4e508d8, 
    context=0x7fffec3715c0, cred_handle=cred_handle@entry=0x7fffec371a20, 
    target_name=target_name@entry=0x7fffec371570) at acquire_cred.c:959
#11 0x00007fffea3ef945 in krb5_gss_init_sec_context_ext (
    minor_status=minor_status@entry=0x7ffff4e508d8, claimant_cred_handle=0x7fffec371a20, 
    claimant_cred_handle@entry=0x0, context_handle=context_handle@entry=0x7fffec36f630, 
    target_name=0x7fffec371570, mech_type=0x7fffea60e5c0 <krb5_gss_oid_array>, 
    req_flags=req_flags@entry=58, time_req=0, input_chan_bindings=0x0, input_token=0x0, 
    actual_mech_type=0x0, output_token=0x7ffff4e508f0, ret_flags=0x7ffff4e508dc, 
    time_rec=0x0, exts=0x7ffff4e50790) at init_sec_context.c:976
#12 0x00007fffea3f0b42 in krb5_gss_init_sec_context (
    minor_status=minor_status@entry=0x7ffff4e508d8, 
    claimant_cred_handle=claimant_cred_handle@entry=0x0, 
    context_handle=context_handle@entry=0x7fffec36f630, target_name=<optimized out>, 
    mech_type=<optimized out>, req_flags=req_flags@entry=58, time_req=0, 
    input_chan_bindings=0x0, input_token=0x0, actual_mech_type=0x0, 
    output_token=0x7ffff4e508f0, ret_flags=0x7ffff4e508dc, time_rec=0x0)
    at init_sec_context.c:1089
#13 0x00007fffea3dbfc8 in gss_init_sec_context (minor_status=0x7ffff4e508d8, 
    claimant_cred_handle=<optimized out>, context_handle=0x7fffec36c2a8, 
    target_name=0x7fffec370090, req_mech_type=<optimized out>, req_flags=58, time_req=0, 
    input_chan_bindings=0x0, input_token=0x0, actual_mech_type=0x0, 
    output_token=0x7ffff4e508f0, ret_flags=0x7ffff4e508dc, time_rec=0x0)
    at g_init_sec_context.c:215
--Type <RET> for more, q to quit, c to continue without paging--
#14 0x00007fffe9d88c83 in ?? () from /usr/lib64/sasl2-3/libgssapiv2.so
#15 0x00007ffff04e04fd in sasl_client_step (conn=conn@entry=0x7fffec376b90, 
    serverin=serverin@entry=0x0, serverinlen=serverinlen@entry=0, 
    prompt_need=prompt_need@entry=0x7ffff4e50aa0, clientout=clientout@entry=0x7ffff4e50ab8, 
    clientoutlen=clientoutlen@entry=0x7ffff4e50a90) at client.c:922
#16 0x00007ffff04e0686 in sasl_client_start (conn=conn@entry=0x7fffec376b90, 
    mechlist=mechlist@entry=0x7ffff7fcb2d8 "GSSAPI", 
    prompt_need=prompt_need@entry=0x7ffff4e50aa0, clientout=clientout@entry=0x7ffff4e50ab8, 
    clientoutlen=clientoutlen@entry=0x7ffff4e50a90, mech=mech@entry=0x7ffff4e50a98)
    at client.c:868
#17 0x00007ffff1171ab7 in ldap_int_sasl_bind (ld=ld@entry=0x7fffec36dc20, dn=dn@entry=0x0, 
    mechs=mechs@entry=0x7ffff7fcb2d8 "GSSAPI", sctrls=sctrls@entry=0x0, 
    cctrls=cctrls@entry=0x0, flags=2, interact=0x7ffff189de20 <ldap_sasl_interact>, 
    defaults=0x7ffff7fbe448, result=0x0, rmech=0x7ffff4e50c60, msgid=0x7ffff4e50c5c)
    at cyrus.c:501
#18 0x00007ffff1174f0b in ldap_sasl_interactive_bind (ld=ld@entry=0x7fffec36dc20, 
    dn=dn@entry=0x0, mechs=mechs@entry=0x7ffff7fcb2d8 "GSSAPI", 
    serverControls=serverControls@entry=0x0, clientControls=clientControls@entry=0x0, 
    flags=flags@entry=2, interact=0x7ffff189de20 <ldap_sasl_interact>, 
    defaults=0x7ffff7fbe448, result=0x0, rmech=0x7ffff4e50c60, msgid=0x7ffff4e50c5c)
    at sasl.c:487
#19 0x00007ffff11750ab in ldap_sasl_interactive_bind_s (ld=0x7fffec36dc20, dn=dn@entry=0x0, 
    mechs=0x7ffff7fcb2d8 "GSSAPI", serverControls=serverControls@entry=0x0, 
    clientControls=clientControls@entry=0x0, flags=flags@entry=2, 
    interact=0x7ffff189de20 <ldap_sasl_interact>, defaults=0x7ffff7fbe448) at sasl.c:521
#20 0x00007ffff189b13b in ldap_reconnect (force=isc_boolean_false, ldap_conn=0x7ffff7fa4640, 
    ldap_inst=0x7ffff7fbe448) at ldap_helper.c:2894
#21 ldap_connect (ldap_inst=ldap_inst@entry=0x7ffff7fbe448, 
    ldap_conn=ldap_conn@entry=0x7ffff7fa4640, force=force@entry=isc_boolean_false)
    at ldap_helper.c:2794
#22 0x00007ffff18a6336 in ldap_pool_connect (ldap_inst=0x7ffff7fbe448, pool=0x7ffff7fc5358)
    at ldap_helper.c:3664
#23 new_ldap_instance (mctx=mctx@entry=0x6bf6d0, db_name=db_name@entry=0x7ffff7fba1c8 "ipa", 
    parameters=parameters@entry=0x7ffff7fbe298 "\n\turi \"ldapi://%2fvar%2frun%2fslapd-IPASL-IPATEST.socket\";\n\tbase \"cn=dns, dc=ipasl,dc=ipatest\";\n\tserver_id \"dcsl.ipasl.ipatest\";\n\tauth_method \"sasl\";\n\tsasl_mech \"GSSAPI\";\n\tsasl_user \"DNS/dcsl.ipasl.ip"..., 
    file=file@entry=0x7ffff7fcb1e0 "/etc/named.conf", line=line@entry=59, 
    dctx=dctx@entry=0x7ffff7fa4448, ldap_instp=<optimized out>) at ldap_helper.c:661
#24 0x00007ffff18989ac in dyndb_init (mctx=0x6bf6d0, name=0x7ffff7fba1c8 "ipa", 
    parameters=0x7ffff7fbe298 "\n\turi \"ldapi://%2fvar%2frun%2fslapd-IPASL-IPATEST.socket\";\n\tbase \"cn=dns, dc=ipasl,dc=ipatest\";\n\tserver_id \"dcsl.ipasl.ipatest\";\n\tauth_method \"sasl\";\n\tsasl_mech \"GSSAPI\";\n\tsasl_user \"DNS/dcsl.ipasl.ip"..., 
    file=0x7ffff7fcb1e0 "/etc/named.conf", line=59, dctx=0x7ffff7fa4448, instp=0x7ffff7fd63f8)
    at ldap_driver.c:1075
#25 0x00007ffff78120f2 in dns_dyndb_load (
    libname=libname@entry=0x7ffff7fa67c0 "/usr/lib64/bind/ldap.so", 
    name=name@entry=0x7ffff7fba1c8 "ipa", 
    parameters=0x7ffff7fbe298 "\n\turi \"ldapi://%2fvar%2frun%2fslapd-IPASL-IPATEST.socket\";\n\tbase \"cn=dns, dc=ipasl,dc=ipatest\";\n\tserver_id \"dcsl.ipasl.ipatest\";\n\tauth_method \"s--Type <RET> for more, q to quit, c to continue without paging--
asl\";\n\tsasl_mech \"GSSAPI\";\n\tsasl_user \"DNS/dcsl.ipasl.ip"..., 
    file=file@entry=0x7ffff7fcb1e0 "/etc/named.conf", line=line@entry=59, 
    mctx=mctx@entry=0x6bf6d0, dctx=0x7ffff7fa4448) at dyndb.c:372
#26 0x000000000042234f in configure_dyndb (dctx=0x7ffff7fa4448, mctx=0x6bf6d0, 
    dyndb=<optimized out>) at ./server.c:1490
#27 configure_view (view=0x7fffec128cf0, viewlist=viewlist@entry=0x7ffff4e529c0, 
    config=0x7ffff7fd87e0, vconfig=vconfig@entry=0x0, 
    cachelist=cachelist@entry=0x7ffff4e529e0, bindkeys=0x7ffff7fde588, mctx=0x6bf6d0, 
    actx=0x7ffff7fa7090, need_hints=<optimized out>) at ./server.c:4741
#28 0x00000000004624be in load_configuration (filename=<optimized out>, 
    server=server@entry=0x7ffff7fb1010, first_time=first_time@entry=isc_boolean_true)
    at ./server.c:7994
#29 0x00000000004638e3 in run_server (task=<optimized out>, event=<optimized out>)
    at ./server.c:8734
#30 0x00007ffff6ca0e79 in dispatch (manager=0x7ffff7fa9010) at task.c:1141
#31 run (uap=0x7ffff7fa9010) at task.c:1313
#32 0x00007ffff643959a in start_thread (arg=0x7ffff4e53700) at pthread_create.c:463
#33 0x00007ffff616efaf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
```
Versions:
freeipa-server-4.7.1-alt3.x86_64
bind-9.11.4.P2-alt1.x86_64
libkrb5-1.16.2-alt1.x86_64

The issue happens on libkrb5-1.16.2, after applying
https://github.com/krb5/krb5/commit/6d784809fe07c2d5f60c1a692bcac08b0d40f0a7.

Ivan Melnikov(ALTLinux maintainer of krb5) suggests to check https://github.com/krb5/krb5/commit/49bb627fed70c5258c151c5135ac3d95ed1ee55d.

Comment 1

Stanislav Levin 2018-11-29 10:12:50 MSK

There is a typo: 389-ds crashes => named (bind-dyndb-ldap plugin) crashes.

Let me check the suggestion against this issue and https://bugzilla.altlinux.org/show_bug.cgi?id=35597 one.

Comment 2

Stanislav Levin 2018-11-29 12:12:56 MSK

There is a typo: 389-ds crashes => named (bind-dyndb-ldap plugin) crashes.

Let me check the suggestion against this issue and https://bugzilla.altlinux.org/show_bug.cgi?id=35597 one.(В ответ на комментарий №1)
> There is a typo: 389-ds crashes => named (bind-dyndb-ldap plugin) crashes.
> 
> Let me check the suggestion against this issue and
> https://bugzilla.altlinux.org/show_bug.cgi?id=35597 one.
I confirm the bug 35597 on libkrb5-1.16.2-alt1. 

But both issues are gone away with @49bb627fed.
I pushed a task #216877.
Please review.

Comment 3

Ivan A. Melnikov 2018-11-29 12:29:37 MSK

> But both issues are gone away with @49bb627fed.
> I pushed a task #216877.

Awesome! And thank you for the great work.

I've approved the subtask 200.

Comment 4

Repository Robot 2018-11-29 13:21:50 MSK

krb5-1.16.2-alt2 -> sisyphus:

Thu Nov 29 2018 Stanislav Levin <slev@altlinux> 1.16.2-alt2
- Fixed yield of cache from MEMORY ccache (closes #35597, #35667).

Wed Aug 29 2018 Alexey Shabalin <shaba@altlinux> 1.16.1-alt2
- rebuild with openssl-1.1

Mon Aug 27 2018 Ivan A. Melnikov <iv@altlinux> 1.16.1-alt1
- 1.16.1 (CVE-2018-5729, CVE-2018-5730)

Mon Jan 22 2018 Evgeny Sinelnikov <sin@altlinux> 1.16-alt1
- Update to latest stable release 1.16

Fri Nov 03 2017 Evgeny Sinelnikov <sin@altlinux> 1.15.2-alt2
- Fix build-pdf on Sisyphus
- Add noport, nss_wrapper and socket_wrapper for tests running

Wed Nov 01 2017 Evgeny Sinelnikov <sin@altlinux> 1.15.2-alt1
- Update to latest stable release 1.15.2 with kdcpreauth from 1.16.x

Sun Aug 20 2017 Evgeny Sinelnikov <sin@altlinux.ru> 1.15.1-alt1
- Update to latest stable release 1.15.1 with kdcpreauth from 1.16.x

Fri Mar 24 2017 Evgeny Sinelnikov <sin@altlinux.ru> 1.14.5-alt1
- Update to first spring release 1.14.5

Tue Feb 28 2017 Evgeny Sinelnikov <sin@altlinux.ru> 1.14.4-alt2
- Add _keytab group for default keytab /etc/krb5.keytab

Wed Feb 15 2017 Evgeny Sinelnikov <sin@altlinux.ru> 1.14.4-alt1
- 1.14.4
- fixed CVE-2016-3120