#7017 NULL LDAP context in call to ldap_search_ext_s during search in cn=ad,cn=trusts,dc=example,dc=com
Closed: fixed 3 years ago Opened 3 years ago by blaman.

...which causes krb5kdc to crash as it hits an assert.

#0  0x00007f38f96611d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f38f96628c8 in __GI_abort () at abort.c:90
#2  0x00007f38f965a146 in __assert_fail_base (fmt=0x7f38f97ab3a8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
    assertion=assertion@entry=0x7f38f26506d3 "ld != ((void *)0)", file=file@entry=0x7f38f264acb6 "search.c", line=line@entry=95,
    function=function@entry=0x7f38f264ad90 <__PRETTY_FUNCTION__.8931> "ldap_pvt_search") at assert.c:92
#3  0x00007f38f965a1f2 in __GI___assert_fail (assertion=assertion@entry=0x7f38f26506d3 "ld != ((void *)0)",
    file=file@entry=0x7f38f264acb6 "search.c", line=line@entry=95,
    function=function@entry=0x7f38f264ad90 <__PRETTY_FUNCTION__.8931> "ldap_pvt_search") at assert.c:101
#4  0x00007f38f261d29c in ldap_pvt_search (ld=ld@entry=0x0, base=base@entry=0x7f38fc6ea1e0 "cn=ad,cn=trusts,dc=example,dc=com",
    scope=scope@entry=2, filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f71110,
    attrsonly=attrsonly@entry=0, sctrls=sctrls@entry=0x0, cctrls=cctrls@entry=0x0, timeout=timeout@entry=0x7f38f2c855d0 <std_timeout>,
    sizelimit=sizelimit@entry=0, deref=deref@entry=-1, msgidp=msgidp@entry=0x7ffd28f71034) at search.c:95
#5  0x00007f38f261d35a in ldap_pvt_search_s (ld=0x0, base=base@entry=0x7f38fc6ea1e0 "cn=ad,cn=trusts,dc=example,dc=com",
    scope=scope@entry=2, filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f71110,
    attrsonly=attrsonly@entry=0, sctrls=sctrls@entry=0x0, cctrls=cctrls@entry=0x0, timeout=timeout@entry=0x7f38f2c855d0 <std_timeout>,
    sizelimit=sizelimit@entry=0, deref=deref@entry=-1, res=res@entry=0x7ffd28f71120) at search.c:174
#6  0x00007f38f261d430 in ldap_search_ext_s (ld=<optimized out>, base=base@entry=0x7f38fc6ea1e0 "cn=ad,cn=trusts,dc=example,dc=com",
    scope=scope@entry=2, filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f71110,
    attrsonly=attrsonly@entry=0, sctrls=sctrls@entry=0x0, cctrls=cctrls@entry=0x0, timeout=timeout@entry=0x7f38f2c855d0 <std_timeout>,
    sizelimit=sizelimit@entry=0, res=res@entry=0x7ffd28f71120) at search.c:150
#7  0x00007f38f2a745d3 in ipadb_simple_search (ipactx=ipactx@entry=0x7f38fc7021b0,
    basedn=0x7f38fc6ea1e0 "cn=ad,cn=trusts,dc=example,dc=com", scope=scope@entry=2,
    filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f71110,
    res=res@entry=0x7ffd28f71120) at ipa_kdb_common.c:189
#8  0x00007f38f2a7b128 in ipadb_mspac_check_trusted_domains (ipactx=ipactx@entry=0x7f38fc7021b0) at ipa_kdb_mspac.c:2378
#9  0x00007f38f2a7b7a8 in ipadb_reinit_mspac (ipactx=ipactx@entry=0x7f38fc7021b0, force_reinit=force_reinit@entry=false)
    at ipa_kdb_mspac.c:2631
#10 0x00007f38f2a73e61 in ipadb_get_connection (ipactx=0x7f38fc7021b0) at ipa_kdb.c:460
#11 0x00007f38f2a74361 in ipadb_need_retry (ipactx=<optimized out>, error=<optimized out>) at ipa_kdb_common.c:149
#12 0x00007f38f2a7452e in ipadb_simple_search (ipactx=ipactx@entry=0x7f38fc7021b0,
    basedn=0x7f38fc704c00 "cn=ad,cn=trusts,dc=example,dc=com", scope=scope@entry=2,
    filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f71360,
    res=res@entry=0x7ffd28f71370) at ipa_kdb_common.c:187
#13 0x00007f38f2a7b128 in ipadb_mspac_check_trusted_domains (ipactx=ipactx@entry=0x7f38fc7021b0) at ipa_kdb_mspac.c:2378
#14 0x00007f38f2a7b7a8 in ipadb_reinit_mspac (ipactx=ipactx@entry=0x7f38fc7021b0, force_reinit=force_reinit@entry=false)
    at ipa_kdb_mspac.c:2631
#15 0x00007f38f2a73e61 in ipadb_get_connection (ipactx=0x7f38fc7021b0) at ipa_kdb.c:460
#16 0x00007f38f2a74361 in ipadb_need_retry (ipactx=<optimized out>, error=<optimized out>) at ipa_kdb_common.c:149
#17 0x00007f38f2a7452e in ipadb_simple_search (ipactx=ipactx@entry=0x7f38fc7021b0,
    basedn=0x7f38fc6e9fb0 "cn=ad,cn=trusts,dc=example,dc=com", scope=scope@entry=2,
    filter=filter@entry=0x7f38f2a819f0 "(objectclass=ipaNTTrustedDomain)", attrs=attrs@entry=0x7ffd28f715b0,
    res=res@entry=0x7ffd28f715c0) at ipa_kdb_common.c:187
#18 0x00007f38f2a7b128 in ipadb_mspac_check_trusted_domains (ipactx=ipactx@entry=0x7f38fc7021b0) at ipa_kdb_mspac.c:2378
#19 0x00007f38f2a7b7a8 in ipadb_reinit_mspac (ipactx=ipactx@entry=0x7f38fc7021b0, force_reinit=force_reinit@entry=false)
    at ipa_kdb_mspac.c:2631
#20 0x00007f38f2a73e61 in ipadb_get_connection (ipactx=0x7f38fc7021b0) at ipa_kdb.c:460
#21 0x00007f38f2a74361 in ipadb_need_retry (ipactx=<optimized out>, error=<optimized out>) at ipa_kdb_common.c:149
#22 0x00007f38f2a747db in ipadb_simple_modify (ipactx=ipactx@entry=0x7f38fc7021b0,
    dn=0x7f38fc6e8e60 "fqdn=ccs-10-22-1-26.hosts.example.com,cn=computers,cn=accounts,dc=example,dc=com", mods=0x7f38fc6ea4b0)
    at ipa_kdb_common.c:252
#23 0x00007f38f2a78a1d in ipadb_modify_principal (entry=0x7f38fc7044b0, kcontext=0x7f38fc701c70) at ipa_kdb_principals.c:2349
#24 ipadb_put_principal (kcontext=kcontext@entry=0x7f38fc701c70, entry=entry@entry=0x7f38fc7044b0, db_args=db_args@entry=0x0)
    at ipa_kdb_principals.c:2367
#25 0x00007f38f2a7e211 in ipadb_audit_as_req (kcontext=0x7f38fc701c70, request=<optimized out>, client=0x7f38fc7044b0,
    server=<optimized out>, authtime=1491042316, error_code=0) at ipa_kdb_audit_as.c:132
#26 0x00007f38fb1dd8d0 in krb5_db_audit_as_req (kcontext=kcontext@entry=0x7f38fc701c70, request=request@entry=0x7f38fc703700,
    client=client@entry=0x7f38fc7044b0, server=server@entry=0x7f38fc704680, authtime=authtime@entry=1491042316,
    error_code=error_code@entry=0) at kdb5.c:2536
#27 0x00007f38fb84a356 in log_as_req (context=0x7f38fc701c70, from=<optimized out>, request=0x7f38fc703700,
    reply=reply@entry=0x7f38fc702ae8, client=0x7f38fc7044b0, cname=<optimized out>, server=0x7f38fc704680,
    sname=0x7f38fc703860 "krbtgt/example.COM@example.COM", authtime=1491042316, status=status@entry=0x0, errcode=errcode@entry=0,
    emsg=emsg@entry=0x0) at kdc_log.c:92
#28 0x00007f38fb839c27 in finish_process_as_req (state=0x7f38fc702920, errcode=<optimized out>) at do_as_req.c:362
#29 0x00007f38fb844aa5 in enc_ts_verify (context=0x7f38fc701c70, req_pkt=<optimized out>, request=<optimized out>,
    enc_tkt_reply=0x7f38fc702958, pa=<optimized out>, cb=<optimized out>, rock=0x7f38fc702a90, moddata=0x0,
    respond=0x7f38fb842ef0 <finish_verify_padata>, arg=0x7f38fc6e9fb0) at kdc_preauth_encts.c:131
#30 0x00007f38fb842e73 in next_padata (state=<optimized out>) at kdc_preauth.c:1178
#31 0x00007f38fb83a7b5 in process_as_req (request=<optimized out>, req_pkt=req_pkt@entry=0x7f38fc703c68,
    from=from@entry=0x7f38fc702808, kdc_active_realm=0x7f38fc6e9e90, vctx=vctx@entry=0x7f38fc6e9b30,
    respond=respond@entry=0x7f38fb8389e0 <finish_dispatch_cache>, arg=arg@entry=0x7f38fc6ff360) at do_as_req.c:819
#32 0x00007f38fb838d02 in dispatch (cb=0x7f38fba552c0 <shandle>, local_saddr=<optimized out>, from=0x7f38fc702808,
    pkt=pkt@entry=0x7f38fc703c68, is_tcp=is_tcp@entry=1, vctx=vctx@entry=0x7f38fc6e9b30,
    respond=respond@entry=0x7f38fb84bf60 <process_tcp_response>, arg=arg@entry=0x7f38fc703be0) at dispatch.c:190
#33 0x00007f38fb84c240 in process_tcp_connection_read (ctx=0x7f38fc6e9b30, ev=0x7f38fc6e8f10) at net-server.c:1739
#34 0x00007f38f99efcd8 in verto_fire (ev=0x7f38fc6e8f10) at verto.c:947
#35 0x00007f38f1d68d8b in epoll_event_loop (tvalp=0x7ffd28f72050, epoll_ev=0x7f38fc709620) at ../tevent_epoll.c:728
#36 epoll_event_loop_once (ev=<optimized out>, location=<optimized out>) at ../tevent_epoll.c:926
#37 0x00007f38f1d67257 in std_event_loop_once (ev=0x7f38fc709a90, location=0x7f38ec6c7132 "verto-tevent.c:55")
    at ../tevent_standard.c:114
#38 0x00007f38f1d6340d in _tevent_loop_once (ev=0x7f38fc709a90, location=0x7f38ec6c7132 "verto-tevent.c:55") at ../tevent.c:533
#39 0x00007f38f99ef4af in verto_run (ctx=ctx@entry=0x7f38fc6e9b30) at verto.c:578
#40 0x00007f38fb837997 in main (argc=5, argv=0x7ffd28f722c8) at main.c:1064

This happens at random intervals, as far as I can tell. Also, I think it might be related to the fact that I turned on ipaNTHash generation on IPA user principals, as I don't otherwise have AD set up. Also, since I was asked about it on IRC: I have run ipa-adtrust-install


I think the problem comes from a complexe handling of ldap connection where ipadb_get_connection can called recursively

IMHO the problem comes from those lines:

#
# up to here the ldap->lcontext is valid (not NULL)
#
/* get adtrust options using default refresh interval */
ret = ipadb_reinit_mspac(ipactx, false);
if (ret && ret != ENOENT) {
    /* TODO: log that there is an issue with adtrust settings */
}

# But here whatever is the result of ipadb_reinit_mspac we return success so that ldap->lcontext will be used
# asserting it is not NULL
ret = 0;

So if ipadb_reinit_mspac resets ipactx->lcontext it will not be detected and it will later assert.
ipadb_reinit_mspac has the ability to reset ipactx->lcontext. For example in the scenario
it calls ipadb_simple_search -> ipadb_need_retry -> ipadb_get_connection ->
<any transient failure ldap_initialize or ldap_set_option or ldap_sasl_bind_s will reset ipactx->lcontext and return EIO>
But the problem is that the returned EIO/failure is ignored in the lines above.

An additional minor issue is that ipadb_need_retry is called with a 'ret' instead of '&ret', so the return code
is not propagated.

I think a fix like could prevent the assert

/* get adtrust options using default refresh interval */
ret = ipadb_reinit_mspac(ipactx, false);
if (ret && ret != ENOENT) {
    /* TODO: log that there is an issue with adtrust settings */                                                                
    goto done;
}
  • a possible scenario is the following one

    ipadb_simple_search
    
    # Here: ipactx->lcontext = cnx_1
    
    # it searches under "cn=ad,cn=trusts,<suffix>" for "(objectclass=ipaNTTrustedDomain)" entries
    # Let assum that this search fails for any reason using cnx_1
    --> ldap_search_ext_s
    <-- ldap_search_ext_s = ERROR
    
    # Here: ipactx->lcontext = cnx_1
    -- > ipadb_need_retry
            --> ipadb_get_connection
    
                # Here: ipactx->lcontext = cnx_2
                --> ipadb_reinit_mspac
                    --> ipadb_mspac_check_trusted_domains
                        --> ipadb_simple_search
    
                            # Here: ipactx->lcontext = cnx_2
    
                            # Let assum that this search fails for any reason (second failure) using cnx_2
                            --> ldap_search_ext_s
                            <-- ldap_search_ext_s = ERROR
    
                            # Here: ipactx->lcontext = cnx_2
                            --> ipadb_need_retry
                                --> ipadb_get_connection
    
                                    # Here ldap_initialize fails so 
                                    #   ipactx->lcontext = NULL
    
                                <-- ipadb_get_connection = EIO           + ipactx->lcontext = NULL
                            <-- ipadb_need_retry         = FALSE         + ipactx->lcontext = NULL
                        <-- ipadb_simple_search          = KRB_ERROR     + ipactx->lcontext = NULL
                    <-- ipadb_mspac_check_trusted_domains= KRB_ERROR     + ipactx->lcontext = NULL
                <-- ipadb_reinit_mspac                   = KRB_ERROR     + ipactx->lcontext = NULL
    
                #
                # does not detect faillure of ipadb_reinit_mspac and returns 0
                #
            <-- ipadb_get_connection  = SUCCESS         + ipactx->lcontext = NULL
    <-- ipadb_need_retry              = TRUE            + ipactx->lcontext = NULL
    
    # Here ipactx->lcontext = NULL and need_retry=TRUE
    # then KDC issue an internal search with a NULL ldapconnection
    --> ldap_search_ext_s
            .... will eventualy abort
    
  • The scenario means there are
    - two consecutive search errors (on different connections)
    - then a failure to open a new connection

After additional investigation I think the scenario is rather:
- two consecutive search errors (on different connections)
- then a failure to establish a new connection that can be one of the following
1- ldap_initialize failure
2- or failure to bind
3- or failure to retrieve config/rootdse
4- or failure to read the connection

Metadata Update from @pvoborni:
- Issue set to the milestone: FreeIPA 4.5.3

3 years ago

Metadata Update from @pvoborni:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1464205

3 years ago

Metadata Update from @pvoborni:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1464205

3 years ago

@blaman can you tell us which distribution and freeipa versions do you run? Would you be able to test the patch @tbordaz produced to see if more changes are needed?

Metadata Update from @tkrizek:
- Issue set to the milestone: FreeIPA 4.5.4 (was: FreeIPA 4.5.3)

3 years ago

master:

  • 0f0423c NULL LDAP context in call to ldap_search_ext_s during search

ipa-4-5:

  • 1cb93ed NULL LDAP context in call to ldap_search_ext_s during search

Metadata Update from @pvomacka:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

3 years ago

@abbra:

tbordaz's patch worked, haven't seen any more crashes since it was deployed on June 30.

I'm running CentOS 7.3.1611 and IPA 4.4.0 (ipa-server-4.4.0-14.el7.centos.7.x86_64) from repos.

Seeing it's been merged into the 4-5 branch, will the patch be in an (hypothetical, as-yet-unreleased) 4.5.4?

Thanks for the testing. It is good to hear that it was a good fix for your environment.

If it is already in the 4-5 branch, then next 4.5.x release will pick it up.

Login to comment on this ticket.

Metadata