I added the correct logfiles now - sorry!

On linux1.linux.intern
1.) service sssd stop; rm -f /var/lib/sss/db/* ; service sssd start
2.) getent passwd user1@aaa

Logfile sssd_linux.intern.log
~~~~~~~~~~~~

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): dbus conn: 23510F0
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): Dispatching.
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sbus_message_handler] (0x4000): Received SBUS method [getDomains]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[be_get_subdomains] (0x0400): Got get subdomains [forced][aaa]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[objectclass=ipaNTTrustedDomain][cn=trusts,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTFlatName]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTTrustedDomainSID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid =
8
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x233b9e0], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_entry]
(0x4000): OriginalDN:
[cn=aaa.intern,cn=ad,cn=trusts,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaNTFlatName]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaNTTrustedDomainSID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x233b9e0], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type:
[LDAP_RES_SEARCH_RESULT]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no
errmsg set
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[objectclass=ipaIDRange][cn=ranges,cn=etc,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaBaseID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaBaseRID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaSecondaryBaseRID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaIDRangeSize]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTTrustedDomainSID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid =
9
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_entry]
(0x4000): OriginalDN:
[cn=LINUX.INTERN_id_range,cn=ranges,cn=etc,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [objectClass]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaBaseID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaBaseRID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaSecondaryBaseRID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaIDRangeSize]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_entry]
(0x4000): OriginalDN:
[cn=AAA.INTERN_id_range,cn=ranges,cn=etc,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [objectClass]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaBaseID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaBaseRID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaIDRangeSize]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaNTTrustedDomainSID]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type:
[LDAP_RES_SEARCH_RESULT]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no
errmsg set
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x233cc00

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x2370a30

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x233cc00 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x2370a30 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x233cc00 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
start ldb transaction (nesting: 0)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
commit ldb transaction (nesting: 0)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2370210

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x234eba0

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2370210 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x234eba0 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2370210 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with
[objectclass=ipaNTDomainAttrs][cn=ad,cn=etc,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTFlatName]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x1000): Requesting attrs:
[ipaNTSecurityIdentifier]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid =
10
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_entry]
(0x4000): OriginalDN:
[cn=linux.intern,cn=ad,cn=etc,dc=linux,dc=intern].
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [cn]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaNTFlatName]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_parse_range]
(0x2000): No sub-attributes for [ipaNTSecurityIdentifier]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234e550], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type:
[LDAP_RES_SEARCH_RESULT]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no
errmsg set
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2376530

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x23765e0

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2376530 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x23765e0 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2376530 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_id_op_destroy] (0x4000): releasing operation connection
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[get_subdomains_callback] (0x0400): Backend returned: (0, 0, <NULL>)
[Success]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[(nil)], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): dbus conn: 23510F0
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): Dispatching.
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sbus_message_handler] (0x4000): Received SBUS method [getAccountInfo]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[be_get_account_info] (0x0100): Got request for [4097][1][name=user1]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_id_op_connect_step] (0x4000): reusing cached connection
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[ipa_s2n_exop_send] (0x0400): Executing extended operation
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[ipa_s2n_exop_send] (0x2000): ldap_extended_operation sent, msgid = 11
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[0x234d040], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_message] (0x4000): Message type: [LDAP_RES_EXTENDED]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[ipa_s2n_exop_done] (0x0400): ldap_extended_operation result:
Success(0), (null)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
start ldb transaction (nesting: 0)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x236f750

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x236f870

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x236f750 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x236f870 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x236f750 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sysdb_search_user_by_name] (0x0400): No such entry
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
start ldb transaction (nesting: 1)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2373ce0

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x236f630

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2373ce0 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x236f630 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2373ce0 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sysdb_search_group_by_name] (0x0400): No such entry
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2373d80

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x236fb00

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2373d80 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x236fb00 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2373d80 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sysdb_search_user_by_uid] (0x0400): No such entry
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
start ldb transaction (nesting: 2)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2381240

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x2381360

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2381240 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x2381360 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2381240 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
commit ldb transaction (nesting: 2)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
start ldb transaction (nesting: 2)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x2381360

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x236f870

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x2381360 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x236f870 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x2381360 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
commit ldb transaction (nesting: 2)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_callback": 0x236f870

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Added timed event "ltdb_timeout": 0x2381360

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Running timer event 0x236f870 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Destroying timer event 0x2381360 "ltdb_timeout"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
Ending timer event 0x236f870 "ltdb_callback"

(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
commit ldb transaction (nesting: 1)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [ldb] (0x4000):
commit ldb transaction (nesting: 0)
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]] [sdap_id_op_done]
(0x4000): releasing operation connection
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: sh[0x234f5c0], connected[1],
ops[(nil)], ldap[0x233f620]
(Wed Sep 10 17:04:24 2014) [sssd[be[linux.intern]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Wed Sep 10 17:04:28 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): dbus conn: 230E920
(Wed Sep 10 17:04:28 2014) [sssd[be[linux.intern]]] [sbus_dispatch]
(0x4000): Dispatching.
(Wed Sep 10 17:04:28 2014) [sssd[be[linux.intern]]]
[sbus_message_handler] (0x4000): Received SBUS method [ping]

~~~~~~~~~~~~


Thanks, Gregor


2014-09-10 8:19 GMT+02:00 Gregor Bregenzer <gregor.bregen...@gmail.com>:
> Hello Sumit,
> i think maybe there is a different problem i just discovered by
> accident. As stated in the first email, i have an AD trust with
> FreeIPA that receives all POSIX attributes from AD, but i get
> different values:
> On the FreeIPA server that has the AD trust (ipa1.linux.intern) i get
> the correct GID (=10000, this is the AD group linuxusers) that is set
> in AD, but on the client (linux1.linux.intern) i get another one ( =
> 10005):
>
> ipa1.linux.intern
> ~~~~
> [root@ipa1 httpd]# getent passwd user1@aaa
> user1@aaa.intern:*:10005:
> 10000:user1:/home/aaa.intern/user1:/bin/bash
>
> -bash-4.2$ id
> uid=10005(user1@aaa.intern) gid=10000(linuxusers@aaa.intern)
> groups=10000(linuxusers@aaa.intern),1933000004(ad_users)
> ~~~~
>
> linux1.linux.intern
> ~~~~~~~~
> [root@linux1 sssd]# getent passwd user1@aaa
> user1@aaa.intern:*:10005:10005::/home/user1@aaa.intern:/bin/bash
>
> [user1@aaa.intern@linux1 ~]$ id
> uid=10005(user1@aaa.intern) gid=10005(user1@aaa.intern)
> Gruppen=10005(user1@aaa.intern),1933000004(ad_users)
>
> Logfile on ipa1.linux.intern sssd_nss.log
> (Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0400):
> Running command [17] with input [user1@aaa.intern].
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_parse_name_for_domains]
> (0x0200): name 'user1@aaa.intern' matched expression for domain
> 'aaa.intern', user is user1                                          │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0100):
> Requesting info for [user1] from [aaa.intern]
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_ncache_check_str]
> (0x2000): Checking negative cache for [NCE/USER/aaa.intern/user1]
>                                                                     │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam_search]
> (0x0100): Requesting info for [user1@aaa.intern]
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_callback": 0x7fe19e562700
>                                                                │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_timeout": 0x7fe19e562830
>                                                                │
> 03│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Running
> timer event 0x7fe19e562700 "ltdb_callback"
>                                                                    │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Destroying
> timer event 0x7fe19e562830 "ltdb_timeout"
>                                                                 │va
> r/│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Ending timer
> event 0x7fe19e562700 "ltdb_callback"
>                                                               │
>   │(Wed Sep 10 08:14:42 2014) [sssd[nss]] [check_cache] (0x0400):
> Cached entry is valid, returning..
>                                                                    │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam_search]
> (0x0400): Returning info for user [user1@aaa.intern]
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [reset_idle_timer] (0x4000):
> Idle timer re-set for client [0x7fe19e563d40][21]
>                                                               │
>
> ----------
> Logfile on linux1.linux.intern sssd_nss.log
>
> (Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_parse_name_for_domains]
> (0x0200): name 'user1@aaa' matched expression for domain 'aaa.intern',
> user is user1                                                 │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam] (0x0100):
> Requesting info for [user1] from [aaa.intern]
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_ncache_check_str]
> (0x2000): Checking negative cache for [NCE/USER/aaa.intern/user1]
>                                                                     │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam_search]
> (0x0100): Requesting info for [user1@aaa.intern]
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_callback": 0x20e2c20
>                                                                │
> (W│
>
>                                                               │
> 00│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_timeout": 0x20e2590
>                                                                │
> (W│
>
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Running
> timer event 0x20e2c20 "ltdb_callback"
>                                                                    │
> (W│
>
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Destroying
> timer event 0x20e2590 "ltdb_timeout"
>                                                                 │
> (W│
>
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Ending timer
> event 0x20e2c20 "ltdb_callback"
>                                                               │
> (W│
>
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_dp_issue_request]
> (0x0400): Issuing request for [0x432730:1:user1@aaa.intern]
>                                                                     │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_dp_get_account_msg]
> (0x0400): Creating request for [aaa.intern][4097][1][name=user1]
>                                                                   │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sbus_add_timeout] (0x2000):
> 0x20d72e0
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_dp_internal_get_send]
> (0x0400): Entering request [0x432730:1:user1@aaa.intern]
>                                                                 │
> 01│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sbus_remove_timeout]
> (0x2000): 0x20d72e0
>                                                                      │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sbus_dispatch] (0x4000):
> dbus conn: 20DB0F0
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sbus_dispatch] (0x4000):
> Dispatching.
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_dp_get_reply] (0x1000):
> Got reply from Data Provider - DP error code: 0 errno: 0 error
> message: Success
> │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_ncache_check_str]
> (0x2000): Checking negative cache for [NCE/USER/aaa.intern/user1]
>                                                                     │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam_search]
> (0x0100): Requesting info for [user1@aaa.intern]
>                                                                  │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_callback": 0x20e8530
>                                                                │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Added timed
> event "ltdb_timeout": 0x20e85e0
>                                                                │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Running
> timer event 0x20e8530 "ltdb_callback"
>                                                                    │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Destroying
> timer event 0x20e85e0 "ltdb_timeout"
>                                                                 │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [ldb] (0x4000): Ending timer
> event 0x20e8530 "ltdb_callback"
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [nss_cmd_getpwnam_search]
> (0x0400): Returning info for user [user1@aaa.intern]
>                                                                  │
> 02│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [sss_dp_req_destructor]
> (0x0400): Deleting request: [0x432730:1:user1@aaa.intern]
>                                                                    │
> :/│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [reset_idle_timer] (0x4000):
> Idle timer re-set for client [0x20e44a0][20]
>                                                               │
>   │(Wed Sep 10 08:14:42 2014) [sssd[nss]] [reset_idle_timer] (0x4000):
> Idle timer re-set for client [0x20e44a0][20]
>                                                               │
> (W│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [client_recv] (0x0200):
> Client disconnected!
>                                                                    │/v
> ar│(Wed Sep 10 08:14:42 2014) [sssd[nss]] [client_destructor]
> (0x2000): Terminated client [0x20e44a0][20]
>
> ~~~~
>
>
> I think i need to get this one right before the HBAC rule - right?
>
>
> Here is my ipa1.linux.intern sssd.conf:
> ~~~~~~~~~
> [domain/linux.intern]
> debug_level=9
> cache_credentials = True
> krb5_store_password_if_offline = True
> ipa_domain = linux.intern
> id_provider = ipa
> auth_provider = ipa
> access_provider = ipa
> ipa_hostname = ipa1.linux.intern
> chpass_provider = ipa
> ipa_server = ipa1.linux.intern
> ipa_server_mode = True
> ldap_tls_cacert = /etc/ipa/ca.crt
> [sssd]
> debug_level=9
> services = nss, sudo, pam, ssh, pac
> config_file_version = 2
> subdomains_provider = ipa
> domains = linux.intern
> [nss]
> debug_level=9
> homedir_substring = /home
>
> [pam]
> debug_level=9
> [sudo]
>
> [autofs]
>
> [ssh]
>
> [pac]
> debug_level=9
> [ifp]
>
> ~~~~~~~~~~~~~~
>
> Here's my linux1.linux.intern sssd.conf
> ~~~~~
> [domain/linux.intern]
> debug_level=9
> cache_credentials = False
> krb5_store_password_if_offline = False
> ipa_domain = linux.intern
> id_provider = ipa
> auth_provider = ipa
> access_provider = ipa
> ipa_hostname = linux1.linux.intern
> chpass_provider = ipa
> ipa_dyndns_update = True
> ipa_server = _srv_, ipa1.linux.intern
> ldap_tls_cacert = /etc/ipa/ca.crt
> use_fully_qualified_domains = True
> # For the SUDO integration
> sudo_provider = ldap
> ldap_uri = ldap://ipa1.linux.intern
> ldap_sudo_search_base = ou=sudoers,dc=linux,dc=intern
> ldap_sasl_mech = GSSAPI
> ldap_sasl_authid = host/linux1.linux.intern
> ldap_sasl_realm = LINUX.INTERN
> krb5_server = ipa1.linux.intern
>
> [sssd]
> debug_level=9
> services = nss, pam, ssh, sudo
> config_file_version = 2
> #default_domain_suffix=aaa.intern
> domains = linux.intern
> [nss]
> debug_level=9
> override_homedir = /home/%u
> override_shell = /bin/bash
> [pam]
> debug_level=9
> [sudo]
>
> [autofs]
>
> [ssh]
> debug_level=9
> [pac]
> debug_level=9
>
> ~~~~
>
>
> I used the following command to create the AD trust:
>
>       ipa trust-add --type=ad aaa.intern --admin Administrator
> --password --range-type ipa-ad-trust-posix
>
> Do you need any other debug information?
>
>
> Thanks!
> Gregor
>
> 2014-09-08 9:17 GMT+02:00 Sumit Bose <sb...@redhat.com>:
>> On Sun, Sep 07, 2014 at 11:41:16PM +0200, Gregor Bregenzer wrote:
>>> Hi!
>>>
>>> I have an AD trust with FreeIPA 4.0.1 and defined a HBAC rule for a
>>> specific user group (=ad_users which is an posix group that has an
>>> external group as member) to login on a specific client
>>> (=linux1.linux.intern).
>>>
>>> The problem is: once i disable the rule and the AD user is not allowed
>>> to login anymore, the user on the client gets another uid and gid via
>>> sssd.
>>>
>>> I use the posix attributes from AD, which will get received by sssd 
>>> perfectly.
>>> The client is running on CentOS 6.5 and uses sssd 1.9.2.129.el6_5.4
>>> AD domain = aaa.intern
>>> IPA domain = linux.intern
>>> AD-User: user1   (uid=1005,gid=10005)
>>>
>>> Here an example:
>>> ----------------------------
>>> 1.) disable the hbac rule and the default allow_all rule:
>>> 2.) check the uid/gid on the client (=linux1.linux.intern) and it looks 
>>> fine:
>>>
>>> [root@linux1 sssd]# getent passwd user1@aaa
>>> user1@aaa.intern:*:10005:10005::/home/user1@aaa.intern:/bin/bash
>>>
>>> 3.) Login with ssh to client as user1. It will be denied upon correct
>>> password input and ssh sessions closes. Up until now everything as
>>> expected. But now:
>>>
>>> 4.) check for the uid/gid on the client - something totally different.
>>> It now also receives the Firstname and Lastname from AD, latter is
>>> empty:
>>>
>>> [root@linux1 sssd]# getent passwd user1@aaa
>>> user1@aaa.intern:*:11601:11601:user1:/home/user1@aaa.intern:/bin/bash
>>>
>>> 5.) Enable the hbac rule and login works, but the unexpected uid/gid
>>> stays the same:
>>>
>>> login as: user1@aaa
>>> user1@aaa@192.168.0.100's password:
>>> login as: user1@aaa
>>> user1@aaa@192.168.0.100's password:
>>> Last failed login: Sun Sep  7 23:19:49 CEST 2014 from 192.168.0.26 on 
>>> ssh:notty
>>> There were 2 failed login attempts since the last successful login.
>>> Creating home directory for user1@aaa.
>>> Last login: Sun Sep  7 23:21:02 2014 from 192.168.0.26
>>> [user1@aaa.intern@linux1 ~]$ id
>>> uid=11601(user1@aaa.intern) gid=11601(user1@aaa.intern)
>>> Gruppen=11601(user1@aaa.intern),1933000004(ad_users)
>>> [user1@aaa.intern@linux1 ~]$
>>> ---------------------------------
>>>
>>> Anyone have a clue what might be the problem?
>>
>> I would expect some kind of collision, but to be sure I need the SSSD
>> log files. Please try to reproduce the switch and send me the log file,
>> if possilbe with debug_level=9.
>>
>> bye,
>> Sumit
>>
>>>
>>> Here's the sssd.conf:
>>> [root@linux1 sssd]# cat /etc/sssd/sssd.conf
>>> [domain/linux.intern]
>>> debug_level=6
>>> cache_credentials = False
>>> krb5_store_password_if_offline = False
>>> ipa_domain = linux.intern
>>> id_provider = ipa
>>> auth_provider = ipa
>>> access_provider = ipa
>>> ipa_hostname = linux1.linux.intern
>>> chpass_provider = ipa
>>> ipa_dyndns_update = True
>>> ipa_server = _srv_, ipa1.linux.intern
>>> ldap_tls_cacert = /etc/ipa/ca.crt
>>> use_fully_qualified_domains = True
>>> # For the SUDO integration
>>> sudo_provider = ldap
>>> ldap_uri = ldap://ipa1.linux.intern
>>> ldap_sudo_search_base = ou=sudoers,dc=linux,dc=intern
>>> ldap_sasl_mech = GSSAPI
>>> ldap_sasl_authid = host/linux1.linux.intern
>>> ldap_sasl_realm = LINUX.INTERN
>>> krb5_server = ipa1.linux.intern
>>> entry_cache_sudo_timeout = 30
>>> [sssd]
>>> debug_level=6
>>> services = nss, pam, ssh, sudo
>>> config_file_version = 2
>>> default_domain_suffix=aaa.intern
>>> domains = linux.intern
>>> [nss]
>>> debug_level=9
>>> override_homedir = /home/%u
>>> override_shell = /bin/bash
>>> [pam]
>>> debug_level=6
>>> [sudo]
>>> debug_level=6
>>> [autofs]
>>>
>>> [ssh]
>>> debug_level=6
>>> [pac]
>>>
>>>
>>>
>>> Thanks!
>>> Gregor
>>>
>>> --
>>> Manage your subscription for the Freeipa-users mailing list:
>>> https://www.redhat.com/mailman/listinfo/freeipa-users
>>> Go To http://freeipa.org for more info on the project
>>
>> --
>> Manage your subscription for the Freeipa-users mailing list:
>> https://www.redhat.com/mailman/listinfo/freeipa-users
>> Go To http://freeipa.org for more info on the project

-- 
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go To http://freeipa.org for more info on the project

Reply via email to