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
--
Cheers,
Tom K.
-------------------------------------------------------------------------------------
Living on earth is expensive, but it includes a free trip around the sun.