8:56 a.m.
Hi List,
I experience sometimes sssd reports certain users as not existing - symptoms in log are
the following:
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5): Received client version
[1].
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam] (4): Requesting info for [paulr]
from [<ALL>]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam_search] (4): Requesting info for
[paulr@default]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request
for [default][4097][1][name=paulr]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 11, Fast
reply - offline) from Data Provider
In this case sssd reports no such a user 'paulr'.
Also, the connection to the ldap server (AD, Windows Server 2008) seems to be quite
unreliable:
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [child_sig_handler] (4): child [20098]
finished successfully.
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [fo_set_port_status] (4): Marking port 389
of server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [set_server_common_status] (4): Marking
server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 14:41:51 2011) [sssd[be[default]]] [sdap_process_result] (4): ldap_result gave
-1, something bad happend!
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
[4099][1][name=postfix]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_resolve_server_done] (4): Found address
for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'KERBEROS'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_set_port_status] (4): Marking port 389
of server 'dcpra1.dublin.ad.s3group.com' as 'not
working'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send] (1): No available
servers for service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [sdap_id_op_connect_done] (1): Failed to
connect, going offline (5 [Input/output error])
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_run_offline_cb] (3): Going offline.
Running callbacks.
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request processed.
Returned 1,11,Offline
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files] (5): Could not
remove
[/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file or directory]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files] (5): Could not
remove
[/var/lib/sss/pubconf/kdcinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file or directory]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files] (5): Could not
remove
[/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file or directory]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
[4097][1][name=paulr]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info] (4): Request
processed. Returned 1,11,Fast reply - offline
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [get_port_status] (4): Reseting the status
of port 389 for server 'dcpra1.dublin.ad.s3group.com'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_resolve_server_done] (4): Found address
for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'KERBEROS'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_resolve_server_done] (4): Found address
for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [sasl_bind_send] (4): Executing sasl bind
mech: GSSAPI, user: draco$(a)DUBLIN.AD.S3GROUP.COM
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [child_sig_handler] (4): child [20584]
finished successfully.
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [fo_set_port_status] (4): Marking port 389
of server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [set_server_common_status] (4): Marking
server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
[4098][1][idnumber=203]
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sysdb_attrs_primary_name] (1): Could not
determine primary name: [22][Invalid argument]
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sdap_save_user] (1): Failed to save the
user - entry has no name attribute
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sdap_save_user] (2): Failed to save user
[Unknown]
Is there any help to this? The client is a RHEL-6 machine.
Thanks,
Ondrej
9:13 a.m.
On Tue, Sep 27, 2011 at 03:56:57PM +0200, Ondrej Valousek wrote:
Hi List,
I experience sometimes sssd reports certain users as not existing -
symptoms in log are the following:
That's because at the time the request came, the SSSD back end was
marked as "offline" and the user was not cached.
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [accept_fd_handler] (4): Client
connected!
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5): Received
client version [1].
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5): Offered
version [1].
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam] (4): Requesting
info for [paulr] from [<ALL>]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam_search] (4):
Requesting info for [paulr@default]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_send_acct_req_create] (4):
Sending request for [default][4097][1][name=paulr]
(Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_get_reply] (4): Got reply
(1, 11, Fast reply - offline) from Data Provider
In this case sssd reports no such a user 'paulr'.
Also, the connection to the ldap server (AD, Windows Server 2008) seems to
be quite unreliable:
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [child_sig_handler] (4):
child [20098] finished successfully.
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [fo_set_port_status] (4):
Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as
'working'
(Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [set_server_common_status]
(4): Marking server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 14:41:51 2011) [sssd[be[default]]] [sdap_process_result] (4):
ldap_result gave -1, something bad happend!
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_get_account_info] (4):
Got request for [4099][1][name=postfix]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send]
(4): Trying to resolve service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_resolve_server_done]
(4): Found address for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send]
(4): Trying to resolve service 'KERBEROS'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_set_port_status] (4):
Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as 'not
working'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send]
(4): Trying to resolve service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_resolve_service_send]
(1): No available servers for service 'LDAP'
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [sdap_id_op_connect_done]
(1): Failed to connect, going offline (5 [Input/output error])
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_run_offline_cb] (3):
Going offline. Running callbacks.
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [acctinfo_callback] (4):
Request processed. Returned 1,11,Offline
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files]
(5): Could not remove
[/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file
or directory]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files]
(5): Could not remove
[/var/lib/sss/pubconf/kdcinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file or
directory]
(Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [remove_krb5_info_files]
(5): Could not remove
[/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file
or directory]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info] (4):
Got request for [4097][1][name=paulr]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info] (4):
Request processed. Returned 1,11,Fast reply - offline
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [fo_resolve_service_send]
(4): Trying to resolve service 'LDAP'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [get_port_status] (4):
Reseting the status of port 389 for server 'dcpra1.dublin.ad.s3group.com'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_resolve_server_done]
(4): Found address for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [fo_resolve_service_send]
(4): Trying to resolve service 'KERBEROS'
(Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_resolve_server_done]
(4): Found address for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [sasl_bind_send] (4):
Executing sasl bind mech: GSSAPI, user: draco$(a)DUBLIN.AD.S3GROUP.COM
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [child_sig_handler] (4):
child [20584] finished successfully.
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [fo_set_port_status] (4):
Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as
'working'
(Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [set_server_common_status]
(4): Marking server 'dcpra1.dublin.ad.s3group.com' as 'working'
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [be_get_account_info] (4):
Got request for [4098][1][idnumber=203]
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sysdb_attrs_primary_name]
(1): Could not determine primary name: [22][Invalid argument]
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sdap_save_user] (1):
Failed to save the user - entry has no name attribute
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sdap_save_user] (2):
Failed to save user [Unknown]
Is there any help to this? The client is a RHEL-6 machine.
Thanks,
What debug_level do you run with? Cau you raise it to 9 so that we see
more info?
9:26 a.m.
On Tue, Sep 27, 2011 at 03:56:57PM +0200, Ondrej Valousek wrote:
> Hi List,
>
> I experience sometimes sssd reports certain users as not existing -
> symptoms in log are the following:
That's because at the time the request came, the SSSD back end was
marked as "offline" and the user was not cached.
Yes, as you suspect, here is your problem: "ldap_result gave -1, something bad
happend"
However, I don't know the reason why that is.
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [accept_fd_handler] (4): Client
> connected!
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5):
> Received client version [1].
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_cmd_get_version] (5):
> Offered version [1].
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam] (4):
> Requesting info for [paulr] from [<ALL>]
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [nss_cmd_getpwnam_search] (4):
> Requesting info for [paulr@default]
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_send_acct_req_create]
> (4): Sending request for [default][4097][1][name=paulr]
> (Tue Sep 27 15:30:17 2011) [sssd[nss]] [sss_dp_get_reply] (4): Got
> reply (1, 11, Fast reply - offline) from Data Provider
>
> In this case sssd reports no such a user 'paulr'.
> Also, the connection to the ldap server (AD, Windows Server 2008)
> seems to be quite unreliable:
> (Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [child_sig_handler]
> (4): child [20098] finished successfully.
> (Tue Sep 27 14:26:40 2011) [sssd[be[default]]] [fo_set_port_status]
> (4): Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as
> 'working' (Tue Sep 27 14:26:40 2011) [sssd[be[default]]]
> [set_server_common_status] (4): Marking server
> 'dcpra1.dublin.ad.s3group.com' as 'working' (Tue Sep 27 14:41:51
> 2011) [sssd[be[default]]] [sdap_process_result] (4): ldap_result gave
> -1, something bad happend!
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [be_get_account_info]
> (4): Got request for [4099][1][name=postfix]
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [be_resolve_server_done] (4): Found address for server
> dcpra1.dublin.ad.s3group.com:
> [192.168.60.203]
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [fo_set_port_status]
> (4): Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as
> 'not working' (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (1): No available servers for service
> 'LDAP'
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [sdap_id_op_connect_done] (1): Failed to connect, going offline (5
> [Input/output error]) (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [be_run_offline_cb] (3): Going offline. Running callbacks.
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]] [acctinfo_callback]
> (4): Request processed. Returned 1,11,Offline
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [remove_krb5_info_files] (5): Could not remove
> [/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such
> file or directory]
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [remove_krb5_info_files] (5): Could not remove
> [/var/lib/sss/pubconf/kdcinfo.DUBLIN.AD.S3GROUP.COM], [2][No such file
> or directory]
> (Tue Sep 27 14:43:50 2011) [sssd[be[default]]]
> [remove_krb5_info_files] (5): Could not remove
> [/var/lib/sss/pubconf/kpasswdinfo.DUBLIN.AD.S3GROUP.COM], [2][No such
> file or directory]
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info]
> (4): Got request for [4097][1][name=paulr]
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [be_get_account_info]
> (4): Request processed. Returned 1,11,Fast reply - offline
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]] [get_port_status] (4):
> Reseting the status of port 389 for server
> 'dcpra1.dublin.ad.s3group.com' (Tue Sep 27 15:30:17 2011)
> [sssd[be[default]]] [be_resolve_server_done] (4): Found address for
> server dcpra1.dublin.ad.s3group.com:
> [192.168.60.203]
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]]
> [fo_resolve_service_send] (4): Trying to resolve service 'KERBEROS'
> (Tue Sep 27 15:30:17 2011) [sssd[be[default]]]
> [be_resolve_server_done] (4): Found address for server
> dcpra1.dublin.ad.s3group.com:
> [192.168.60.203]
> (Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [sasl_bind_send] (4):
> Executing sasl bind mech: GSSAPI, user: draco$(a)DUBLIN.AD.S3GROUP.COM
> (Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [child_sig_handler]
> (4): child [20584] finished successfully.
> (Tue Sep 27 15:30:18 2011) [sssd[be[default]]] [fo_set_port_status]
> (4): Marking port 389 of server 'dcpra1.dublin.ad.s3group.com' as
> 'working' (Tue Sep 27 15:30:18 2011) [sssd[be[default]]]
> [set_server_common_status] (4): Marking server
> 'dcpra1.dublin.ad.s3group.com' as 'working' (Tue Sep 27 15:38:40
> 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
> [4098][1][idnumber=203]
> (Tue Sep 27 15:38:40 2011) [sssd[be[default]]]
> [sysdb_attrs_primary_name] (1): Could not determine primary name:
> [22][Invalid argument] (Tue Sep 27 15:38:40 2011) [sssd[be[default]]]
> [sdap_save_user] (1): Failed to save the user - entry has no name
> attribute
> (Tue Sep 27 15:38:40 2011) [sssd[be[default]]] [sdap_save_user] (2):
> Failed to save user [Unknown]
>
> Is there any help to this? The client is a RHEL-6 machine.
> Thanks,
What debug_level do you run with? Cau you raise it to 9 so that we see
more info?
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://fedorahosted.org/mailman/listinfo/sssd-devel
--
Thank you
Jan Zeleny
Red Hat Software Engineer
Brno, Czech Republic
9:43 a.m.
On Tue, 2011-09-27 at 16:26 +0200, Jan Zelený wrote:
> On Tue, Sep 27, 2011 at 03:56:57PM +0200, Ondrej Valousek
wrote:
> > Hi List,
> >
> > I experience sometimes sssd reports certain users as not existing -
>
> > symptoms in log are the following:
> That's because at the time the request came, the SSSD back end was
> marked as "offline" and the user was not cached.
Yes, as you suspect, here is your problem: "ldap_result gave -1, something bad
happend"
However, I don't know the reason why that is.
Yeah, we see this every once in a while. Usually it means that Active
Directory returned something that violates the LDAP protocol.
Unfortunately, the openldap libraries don't provide us any way to ask
what error it actually detected.
But the short version is that it's nearly always a server issue.
10:56 a.m.
On 09/27/2011 04:13 PM, Jakub Hrozek wrote:
What debug_level do you run with? Cau you raise it to 9 so that we
see
more info?
I am here again with debug log 7:
Note that the errors begin 15 minutes after successfully connecting to the LDAP server for
the first time. Just a matter of interest, how
long are we keeping the ldap connection to the server? Is it possible to limit it
somehow?
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sdap_get_generic_done] (6): Search result:
Success(0), (null)
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [save_rfc2307bis_user_memberships] (7):
Save parent groups to sysdb
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sysdb_search_groups] (6): Search groups
with filter:
(&(objectclass=group)(member=name=kiranr,cn=users,cn=default,cn=sysdb))
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sysdb_search_groups] (6): Error: 2 (No
such file or directory)
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [save_rfc2307bis_user_memberships] (6):
User [kiranr] is not a direct member of any groups
(Thu Oct 6 *17:10:01* 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request
processed. Returned 0,0,Success
(Thu Oct 6 *17:25:30* 2011) [sssd[be[default]]] [sdap_process_result] (4): ldap_result
gave -1, something bad happend!
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
[4099][1][name=webserv]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [resolve_srv_send] (6): The status of SRV
lookup is resolved
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_resolve_server_done] (4): Found address
for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_uri_callback] (6): Constructed uri
'ldap://dcpra1.dublin.ad.s3group.com:389'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (6): calling
ldap_search_ext with [(objectclass=*)][].
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [*]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [altServer]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [namingContexts]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedControl]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedExtension]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedFeatures]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedLDAPVersion]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedSASLMechanisms]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [defaultNamingContext]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [lastUSN]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [highestCommittedUSN]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_done] (6): Search result:
Success(0), (null)
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_kinit_send] (6): Attempting kinit
((null), draco$(a)DUBLIN.AD.S3GROUP.COM,
DUBLIN.AD.S3GROUP.COM, 86400)
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_kinit_next_kdc] (7): Resolving next
KDC for service KERBEROS
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'KERBEROS'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
0 for server '(no name)' is 'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (4): Reseting the status
of port 0 for server '(no name)'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [resolve_srv_send] (6): The status of SRV
lookup is not resolved
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_set_port_status] (4): Marking port 389
of server 'dcpra1.dublin.ad.s3group.com' as 'not
working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (1): No available
servers for service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_id_op_connect_done] (1): Failed to
connect, going offline (5 [Input/output error])
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_run_offline_cb] (3): Going offline.
Running callbacks.
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request processed.
Returned 1,11,Offline
11:24 a.m.
Confirmed - the default timeout for idle LDAP connections is set 900 seconds on AD based
ldap servers - so we should be able to close the
connection after some time if nothing else is needed (just to conserve resources, if not
for anything else....).
Ondrej
On 10/06/2011 05:56 PM, Ondrej Valousek wrote:
On 09/27/2011 04:13 PM, Jakub Hrozek wrote:
> What debug_level do you run with? Cau you raise it to 9 so that we see
> more info?
I am here again with debug log 7:
Note that the errors begin 15 minutes after successfully connecting to the LDAP server
for the first time. Just a matter of interest, how
long are we keeping the ldap connection to the server? Is it possible to limit it
somehow?
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sdap_get_generic_done] (6): Search
result: Success(0), (null)
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [save_rfc2307bis_user_memberships] (7):
Save parent groups to sysdb
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sysdb_search_groups] (6): Search groups
with filter:
(&(objectclass=group)(member=name=kiranr,cn=users,cn=default,cn=sysdb))
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [sysdb_search_groups] (6): Error: 2 (No
such file or directory)
(Thu Oct 6 17:10:01 2011) [sssd[be[default]]] [save_rfc2307bis_user_memberships] (6):
User [kiranr] is not a direct member of any groups
(Thu Oct 6 *17:10:01* 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request
processed. Returned 0,0,Success
(Thu Oct 6 *17:25:30* 2011) [sssd[be[default]]] [sdap_process_result] (4): ldap_result
gave -1, something bad happend!
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_get_account_info] (4): Got request for
[4099][1][name=webserv]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [resolve_srv_send] (6): The status of SRV
lookup is resolved
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_resolve_server_done] (4): Found
address for server dcpra1.dublin.ad.s3group.com:
[192.168.60.203]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_uri_callback] (6): Constructed uri
'ldap://dcpra1.dublin.ad.s3group.com:389'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (6): calling
ldap_search_ext with [(objectclass=*)][].
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [*]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [altServer]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [namingContexts]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedControl]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedExtension]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedFeatures]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedLDAPVersion]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [supportedSASLMechanisms]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [defaultNamingContext]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [lastUSN]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_send] (7): Requesting
attrs: [highestCommittedUSN]
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_get_generic_done] (6): Search
result: Success(0), (null)
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_kinit_send] (6): Attempting kinit
((null), draco$(a)DUBLIN.AD.S3GROUP.COM,
DUBLIN.AD.S3GROUP.COM, 86400)
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_kinit_next_kdc] (7): Resolving next
KDC for service KERBEROS
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'KERBEROS'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
0 for server '(no name)' is 'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (4): Reseting the status
of port 0 for server '(no name)'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [resolve_srv_send] (6): The status of SRV
lookup is not resolved
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_set_port_status] (4): Marking port 389
of server 'dcpra1.dublin.ad.s3group.com' as 'not
working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (4): Trying to
resolve service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_server_status] (7): Status of server
'dcpra1.dublin.ad.s3group.com' is 'working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [get_port_status] (7): Port status of port
389 for server 'dcpra1.dublin.ad.s3group.com' is
'not working'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [fo_resolve_service_send] (1): No
available servers for service 'LDAP'
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [sdap_id_op_connect_done] (1): Failed to
connect, going offline (5 [Input/output error])
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [be_run_offline_cb] (3): Going offline.
Running callbacks.
(Thu Oct 6 17:26:40 2011) [sssd[be[default]]] [acctinfo_callback] (4): Request
processed. Returned 1,11,Offline
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://fedorahosted.org/mailman/listinfo/sssd-devel
11:34 a.m.
On Thu, 2011-10-06 at 18:24 +0200, Ondrej Valousek wrote:
Confirmed - the default timeout for idle LDAP connections is set 900
seconds on AD based ldap servers - so we should be able to close the
connection after some time if nothing else is needed (just to conserve
resources, if not for anything else....).
Well, the real issue here is that the openldap client libraries that
we're using are returning a generic error instead of reporting that the
connection was terminated.
We don't really want to implement an internal timeout (we actually
retain the connection on purpose, so we don't have to go through the
slow ldap bind on every request). What we want is to be able to notice
that we received an idle disconnect from the server and reconnect
(rather than doing what we do now, which is treat it as if the server
has become unavailable and fail over to the next one).
2:47 a.m.
On 10/06/2011 06:34 PM, Stephen Gallagher wrote:
Well, the real issue here is that the openldap client libraries that
we're using are returning a generic error instead of reporting that the
connection was terminated.
So shall I open a RFE against openldap then?
We don't really want to implement an internal timeout (we
actually
retain the connection on purpose, so we don't have to go through the
slow ldap bind on every request). What we want is to be able to notice
that we received an idle disconnect from the server and reconnect
(rather than doing what we do now, which is treat it as if the server
has become unavailable and fail over to the next one).
I do not think this is the
best approach - imagine 100+ client machines bound simultaneously to the single LDAP
server. It can easily run
out of resources.
I am also not saying we should close the connection after each request. We should probably
close it actively if being idle for some time.
I know that for example automounter does not keep the connection open for this purpose.
It would be interesting to see what is the general recommendation regarding this problem.
Anyone from Samba team listening? How it is done in winbind, for example?
Thanks,
Ondrej
6:43 a.m.
On Fri, 2011-10-07 at 09:47 +0200, Ondrej Valousek wrote:
On 10/06/2011 06:34 PM, Stephen Gallagher wrote:
> Well, the real issue here is that the openldap client libraries that
> we're using are returning a generic error instead of reporting that the
> connection was terminated.
So shall I open a RFE against openldap then?
I'll take care of that sometime soon.
> We don't really want to implement an internal timeout (we
actually
> retain the connection on purpose, so we don't have to go through the
> slow ldap bind on every request). What we want is to be able to notice
> that we received an idle disconnect from the server and reconnect
> (rather than doing what we do now, which is treat it as if the server
> has become unavailable and fail over to the next one).
I do not think this is the best approach - imagine 100+ client
machines bound simultaneously to the single LDAP server. It can easily
run out of resources.
I am also not saying we should close the connection after each
request. We should probably close it actively if being idle for some
time.
I know that for example automounter does not keep the connection open
for this purpose.
Yeah, I'm convinced that we need to allow a configurable idle timeout
for the SSSD LDAP connections. Please log an enhancement ticket upstream
at https://fedorahosted.org/sssd if you have a Fedora account. If not,
feel free to file a bug on whichever distro is appropriate, and post it
here.
It would be interesting to see what is the general recommendation
regarding this problem.
Anyone from Samba team listening? How it is done in winbind, for
example?
Thanks,
Ondrej
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://fedorahosted.org/mailman/listinfo/sssd-devel
8:02 a.m.
I'll take care of that sometime soon.
RFE #744132 opened in
the RHEL bugzilla
Yeah, I'm convinced that we need to allow a configurable idle timeout
for the SSSD LDAP connections. Please log an enhancement ticket upstream
at https://fedorahosted.org/sssd if you have a Fedora account. If not,
feel free to file a bug on whichever distro is appropriate, and post it
here.
RFE #744197 opened in the RHEL bugzilla
Thanks!
Ondrej
9:15 a.m.
On Tue, Sep 27, 2011 at 03:56:57PM +0200, Ondrej Valousek wrote:
(Tue Sep 27 15:38:40 2011) [sssd[be[default]]]
[sysdb_attrs_primary_name]
(1): Could not determine primary name: [22][Invalid argument]
Actually this is interesting as well.
What version exactly are you running? There was a couple of patches
recently to improve the behaviour of users with multiple names..
4578
days inactive
4588
days old
sssd-devel@lists.fedorahosted.org
10 comments
4 participants
participants (4)
-
Jakub Hrozek -
Jan Zelený -
Ondrej Valousek -
Stephen Gallagher