On 1/31/2018 2:34 PM, Jakub Hrozek via FreeIPA-users wrote:
> On Wed, Jan 31, 2018 at 01:18:27PM -0500, TomK via FreeIPA-users wrote:
>> On 1/31/2018 12:21 PM, TomK wrote:
>>> On 1/31/2018 9:41 AM, Jakub Hrozek wrote:
>>>> See inline..
>>>>
>>>> On Wed, Jan 31, 2018 at 03:23:57AM -0500, TomK wrote:
>>>>> On 1/31/2018 3:18 AM, TomK via FreeIPA-users wrote:
>>>>> My bad, did not include sssd-users earlier. :(
>>>>>
>>>>>> Hey All,
>>>>>>
>>>>>> I'm wondering if anyone came across this error below. We
have
>>>>>> two RHEL
>>>>>> 7.4 servers with SSSD 1.15.2: http-srv01 and http-srv02
>>>>>>
>>>>>> Both connect to the same AD DC host below:
addc-srv03.addom.com.
>>>>>> Verified krb5.conf and sssd.conf both are identical. We can
>>>>>> login on
>>>>>> the http-srv01 and can list all groups for an AD account.
>>>>>>
>>>>>> On http-srv02 we cannot login and any group listing from the CLI
>>>>>> result
>>>>>> only in the user's local groups. No AD groups.
>>>>>>
>>>>>> Logs give us the output below. Short of adding in the entire log
>>>>>> which
>>>>>> I might not be able to do till the end of the week, what could we
>>>>>> look
>>>>>> at to resolve this?
>>>>>>
>>>>>> There's very little available online on this error. The RH
solution
>>>>>> doesn't make sense since the first host connects and
>>>>>> authenticates users
>>>>>> just fine so it's definitely GC enabled.
>>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Cheers,
>>>>> Tom K.
>>>>>
-------------------------------------------------------------------------------------
>>>>>
>>>>>
>>>>>
>>>>> Living on earth is expensive, but it includes a free trip around
>>>>> the sun.
>>>>>
>>>>>
>>>>>
>>>>> samba-libs-4.6.2-12.el7_4.x86_64
>>>>> samba-client-libs-4.6.2-12.el7_4.x86_64
>>>>> sssd-1.15.2-50.el7_4.6.x86_64
>>>>> openldap-2.4.44-5.el7.x86_64
>>>>> sssd-ldap-1.15.2-50.el7_4.6.x86_64
>>>>> sssd-common-pac-1.15.2-50.el7_4.6.x86_64
>>>>> samba-winbind-clients-4.6.2-12.el7_4.x86_64
>>>>> samba-common-4.6.2-12.el7_4.noarch
>>>>> sssd-client-1.15.2-50.el7_4.6.x86_64
>>>>> sssd-proxy-1.15.2-50.el7_4.6.x86_64
>>>>> samba-winbind-modules-4.6.2-12.el7_4.x86_64
>>>>> python-sssdconfig-1.15.2-50.el7_4.6.noarch
>>>>> sssd-ipa-1.15.2-50.el7_4.6.x86_64
>>>>> samba-common-libs-4.6.2-12.el7_4.x86_64
>>>>> sssd-krb5-common-1.15.2-50.el7_4.6.x86_64
>>>>> samba-winbind-4.6.2-12.el7_4.x86_64
>>>>> sssd-krb5-1.15.2-50.el7_4.6.x86_64
>>>>> sssd-ad-1.15.2-50.el7_4.6.x86_64
>>>>> sssd-common-1.15.2-50.el7_4.6.x86_64
>>>>> samba-common-tools-4.6.2-12.el7_4.x86_64
>>>>>
>>>>>
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [sbus_dispatch]
>>>>> (0x4000): dbus
>>>>> conn: 0x55b2e22e8700
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [sbus_dispatch]
>>>>> (0x4000):
>>>>> Dispatching.
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [sbus_message_handler]
>>>>> (0x2000): Received SBUS method
>>>>> org.freedesktop.sssd.dataprovider.getAccountInfo on path
>>>>> /org/freedesktop/sssd/dataprovider
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]]
>>>>> [sbus_get_sender_id_send]
>>>>> (0x2000): Not a sysbus message, quit
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]]
>>>>> [dp_get_account_info_handler]
>>>>> (0x0200): Got request for
>>>>> [0x2][BE_REQ_GROUP][name=unix-admin-group@addom]
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [dp_attach_req]
>>>>> (0x0400): DP
>>>>> Request [Account #4]: New request. Flags [0x0001].
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [dp_attach_req]
>>>>> (0x0400):
>>>>> Number of active DP request: 1
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [sss_domain_get_state]
>>>>> (0x1000): Domain ADDOM is Active
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [sss_domain_get_state]
>>>>> (0x1000): Domain ADDOM is Active
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]]
>>>>> [sdap_id_op_connect_step]
>>>>> (0x4000): beginning to connect
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]]
>>>>> [fo_resolve_service_send]
>>>>> (0x0100): Trying to resolve service 'AD_GC'
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [get_server_status]
>>>>> (0x1000):
>>>>> Status of server 'addc-srv03.addom.com' is 'working'
>>>>> (Tue Jan 30 19:00:01 2018) [sssd[be[ADDOM]]] [get_port_status]
>>>>> (0x1000):
>>>>> Port status of port 0 for server 'addc-srv03.addom.com' is
'not
>>>>> working'
>>>>
>>>> What debug level are you running with? Is this the first occurence of
>>>> 'port not working' since sssd started?
>>> It's debug_level = 9. There was 1002 occurrances since I restarted
>>> sssd
>>> last night. If it's F/W, I'm not clear on the port this is
referring
>>> too.
>> Also confirmed that port 3268 from both clients to the AD DC is
>> blocked in
>> F/W. However then that raises the question why authentication works on
>> http-srv01 even though traffic to port 3268 is also getting denied
>> from that
>> host.
>
> The 'port' here refers to an internal sssd structure that usually maps
> to a network port, but not always.
>
> Is there some more context around the very first 'not working' since the
> sssd restart? Because here is not much, there's just connecting and then
> not working which leaves me puzzled.
>
> The very first state switch should have a message from
> "_be_fo_set_port_status" which also includes who was the caller etc.
> That should give some more context.
> _______________________________________________
> FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
> To unsubscribe send an email to
> freeipa-users-leave(a)lists.fedorahosted.org
>
Below is the snippet.
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [ldb] (0x4000): Destroying
timer event 0x55d9c6aa2020 "ltdb_timeout"
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [ldb] (0x4000): Ending
timer event 0x55d9c6ab2370 "ltdb_callback"
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [check_if_pac_is_available]
(0x4000): No PAC available.
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [sdap_id_op_connect_step]
(0x4000): beginning to connect
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'AD_GC'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [get_server_status]
(0x1000): Status of server 'addc-srv01.addom.com' is 'working'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [get_port_status] (0x1000):
Port status of port 0 for server 'addc-srv01.addom.com' is 'neutral'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6
seconds
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [get_server_status]
(0x1000): Status of server 'addc-srv01.addom.com' is 'working'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [be_resolve_server_process]
(0x1000): Saving the first resolved server
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [be_resolve_server_process]
(0x0200): Found address for server
addc-srv01.addom.com: [49.4.165.26]
TTL 2010
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [ad_resolve_callback]
(0x0100): Constructed uri 'ldap://addc-srv01.addom.com'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]] [ad_resolve_callback]
(0x0100): Constructed GC uri 'ldap://addc-srv01.addom.com:3268'
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]]
[sssd_async_socket_init_send] (0x4000): Using file descriptor [25] for
the connection.
(Wed Jan 31 13:28:09 2018) [sssd[be[ADDOM]]]
[sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for
connecting
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]]
[sssd_async_connect_timeout] (0x0100): The connection timed out
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]]
[sssd_async_socket_init_done] (0x0020): sdap_async_sys_connect request
failed: [110]: Connection
timed out.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]]
[sssd_async_socket_state_destructor] (0x0400): closing socket [25]
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]]
[sss_ldap_init_sys_connect_done] (0x0020): sssd_async_socket_init
request failed: [110]: Connection
timed out.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sdap_sys_connect_done]
(0x0020): sdap_async_connect_call request failed: [110]: Connection timed
out.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sdap_handle_release]
(0x2000): Trace: sh[0x55d9c6abe520], connected[0], ops[(nil)], ldap[(nil)],
destructor_lock[0], release_memory[0]
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [_be_fo_set_port_status]
(0x8000): Setting status: PORT_NOT_WORKING. Called from:
src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_done: 1572
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [fo_set_port_status]
(0x0100): Marking port 0 of server 'addc-srv01.addom.com' as 'not
working'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [fo_set_port_status]
(0x0400): Marking port 0 of duplicate server 'addc-srv01.addom.com' as 'not
working'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'AD_GC'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [get_server_status]
(0x1000): Status of server 'addc-srv01.addom.com' is 'working'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [get_port_status] (0x1000):
Port status of port 0 for server 'addc-srv01.addom.com' is 'not working'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [get_port_status] (0x0080):
SSSD is unable to complete the full connection request, this internal
status does not necessarily indicate network port issues.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [fo_resolve_service_send]
(0x0020): No available servers for service 'AD_GC'
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [be_resolve_server_done]
(0x1000): Server resolution failed: [5]: Input/output error
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sdap_id_op_connect_done]
(0x0400): Failed to connect to server, but ignore mark offline is enabled.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sdap_id_op_connect_done]
(0x4000): notify error to op #1: 5 [Input/output error]
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_done] (0x0400): DP
Request [Initgroups #1]: Request handler finished [0]: Success
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [_dp_req_recv] (0x0400): DP
Request [Initgroups #1]: Receiving request data.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_initgr_pp]
(0x0400): Ordering NSS responder to update memory cache
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_reply_list_success]
(0x0400): DP Request [Initgroups #1]: Finished. Success.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_reply_std]
(0x1000): DP Request [Initgroups #1]: Returning [Internal Error]:
3,5,Init group
lookup failed
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_table_value_destructor]
(0x0400): Removing [0:1:0x0001:3::ADDOM:name=johndoe4@addom] from reply
table
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_destructor]
(0x0400): DP Request [Initgroups #1]: Request removed.
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [dp_req_destructor]
(0x0400): Number of active DP request: 0
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sdap_id_release_conn_data]
(0x4000): releasing unused connection
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sbus_dispatch] (0x4000):
dbus conn: 0x55d9c6a91aa0
(Wed Jan 31 13:28:15 2018) [sssd[be[ADDOM]]] [sbus_dispatch] (0x4000):
Dispatching.
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [sbus_dispatch] (0x4000):
dbus conn: 0x55d9c6aac8b0
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [sbus_dispatch] (0x4000):
Dispatching.
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [sbus_message_handler]
(0x2000): Received SBUS method
org.freedesktop.sssd.dataprovider.getAccountInfo on path
/org/freedesktop/sssd/dataprovider
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [sbus_get_sender_id_send]
(0x2000): Not a sysbus message, quit
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]]
[dp_get_account_info_handler] (0x0200): Got request for
[0x3][BE_REQ_INITGROUPS][name=johndoe4@addom]
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [sss_domain_get_state]
(0x1000): Domain ADDOM is Active
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [ldb] (0x4000): Added timed
event "ltdb_callback": 0x55d9c6a8fa70
(Wed Jan 31 13:28:22 2018) [sssd[be[ADDOM]]] [ldb] (0x4000): Added timed
event "ltdb_timeout": 0x55d9c6ac9de0
I've tried the parameter ad_enable_gc = False in the sssd.conf on the
non working host. This got past the group error but the login then
fails with:
[-1765328243][Can't find client principal JOHNDOE4(a)ADDOM.COM in cache
collection]
This is preceeded by:
sssd_send_pac_ failed, group membership for user with principal
[JOHNDOE4\@ADDOM.COM(a)ADDOM.COM] might not be correct.
So I'm removing that option again since I'm not sure if that's is an
improvement on the existing situation.
--
Cheers,
Tom K.
-------------------------------------------------------------------------------------
Living on earth is expensive, but it includes a free trip around the sun.