sssd troubles under load

[Orion Poplawski]

We're having some trouble with sssd on centos 7 under load on a VPS. 
389ds ldap server for id/auth.  Part may be an issue with the VPS, but 
I'm trying to track down all possible issues.

Also, we realized that we were running in a bit of a bad state - the 
primary ldap server was not available, but the backup was.

Some logs:

General question, is this bad?:
(Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done] 
(0x0040): Failed to retrieve users

see that fairly frequently.

Trouble:
(Tue Jan  6 22:30:31 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:30:36 2015) [sssd[be[default]]] 
[resolv_gethostbyname_done] (0x0040): querying hosts database failed 
[5]: Input/output error
(Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [fo_resolve_service_done] 
(0x0020): Failed to resolve server 'server.com': Timeout while 
contacting DNS servers
(Tue Jan  6 22:30:36 2015) [sssd[be[default]]] 
[be_resolve_server_process] (0x0080): Couldn't resolve server 
(server.com), resolver returned (5)
(Tue Jan  6 22:30:45 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [fo_resolve_service_send] 
(0x0020): No available servers for service 'LDAP'
(Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_id_op_connect_done] 
(0x0020): Failed to connect, going offline (5 [Input/output error])
(Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [be_run_offline_cb] 
(0x0080): Going offline. Running callbacks.
(Tue Jan  6 22:31:52 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:31:52 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:31:52 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:31:52 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [fo_resolve_service_send] 
(0x0020): No available servers for service 'LDAP'
(Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [sdap_id_op_connect_done] 
(0x0020): Failed to connect, going offline (5 [Input/output error])
(Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [be_run_offline_cb] 
(0x0080): Going offline. Running callbacks.
(Tue Jan  6 22:33:07 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:33:07 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:33:07 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:33:07 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:33:08 2015) [sssd[be[default]]] 
[get_single_value_as_string] (0x0080): More than one value found.
(Tue Jan  6 22:33:08 2015) [sssd[be[default]]] 
[sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
(Tue Jan  6 22:33:14 2015) [sssd[be[default]]] 
[get_single_value_as_string] (0x0080): More than one value found.
(Tue Jan  6 22:33:14 2015) [sssd[be[default]]] 
[sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] 
[be_resolve_server_process] (0x0040): The fail over cycled through all 
available servers
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] 
(0x0080): Going offline. Running callbacks.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] 
[be_resolve_server_process] (0x0040): The fail over cycled through all 
available servers
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] 
(0x0080): Going offline. Running callbacks.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] 
[be_resolve_server_process] (0x0040): The fail over cycled through all 
available servers
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] 
(0x0080): Going offline. Running callbacks.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:34:16 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:34:16 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.
(Tue Jan  6 22:34:16 2015) [sssd[be[default]]] 
[sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect 
request failed.
(Tue Jan  6 22:34:16 2015) [sssd[be[default]]] [sdap_sys_connect_done] 
(0x0020): sdap_async_connect_call request failed.

don't know why it wasn't able to reconnect to the backup, or perhaps it 
did, but just not logged.

[Jakub Hrozek]

On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying
> to track down all possible issues.
>
> Also, we realized that we were running in a bit of a bad state - the primary
> ldap server was not available, but the backup was.
>
> Some logs:
>
> General question, is this bad?:
> (Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done]
> (0x0040): Failed to retrieve users

This can be caused by many things, we neer more context..in general, the
LDAP search has failed and SSSD would fall back to cached entries.
> see that fairly frequently.
>
> Trouble:
> (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [resolv_gethostbyname_done]
> (0x0040): querying hosts database failed [5]: Input/output error
> (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [fo_resolve_service_done]
> (0x0020): Failed to resolve server 'server.com': Timeout while contacting
> DNS servers
> (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [be_resolve_server_process]
> (0x0080): Couldn't resolve server (server.com), resolver returned (5)

This seems like the core issue, can you resolve server.com from outside
SSSD (with dig, maybe) ?
> (Tue Jan  6 22:30:45 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [fo_resolve_service_send]
> (0x0020): No available servers for service 'LDAP'
> (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_id_op_connect_done]
> (0x0020): Failed to connect, going offline (5 [Input/output error])
> (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> Going offline. Running callbacks.

Here SSSD goes offline and the front end would switch to using the
cache.
> (Tue Jan  6 22:31:52 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:31:52 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:31:52 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:31:52 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [fo_resolve_service_send]
> (0x0020): No available servers for service 'LDAP'
> (Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [sdap_id_op_connect_done]
> (0x0020): Failed to connect, going offline (5 [Input/output error])
> (Tue Jan  6 22:32:00 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> Going offline. Running callbacks.
> (Tue Jan  6 22:33:07 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:33:07 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:33:07 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:33:07 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:33:08 2015) [sssd[be[default]]] [get_single_value_as_string]
> (0x0080): More than one value found.
> (Tue Jan  6 22:33:08 2015) [sssd[be[default]]]
> [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> (Tue Jan  6 22:33:14 2015) [sssd[be[default]]] [get_single_value_as_string]
> (0x0080): More than one value found.

This is weird as well, here SSSD is complaining that defaultNamingContext
attribute of rootDSE contains multiple values. But I don't see SSSD grabbing
the rootDSE anywhere at all..what log level did you use?

You can read the rootDSE manually using:
ldapsearch -x -H ldap://server.com -s base -b "" defaultNamingContext
> (Tue Jan  6 22:33:14 2015) [sssd[be[default]]]
> [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_resolve_server_process]
> (0x0040): The fail over cycled through all available servers
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> Going offline. Running callbacks.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_resolve_server_process]
> (0x0040): The fail over cycled through all available servers
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> Going offline. Running callbacks.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_resolve_server_process]
> (0x0040): The fail over cycled through all available servers
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> Going offline. Running callbacks.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:34:06 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:34:16 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:34:16 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
> (Tue Jan  6 22:34:16 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> failed.
> (Tue Jan  6 22:34:16 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.
>
> don't know why it wasn't able to reconnect to the backup, or perhaps it did,
> but just not logged.

[Orion Poplawski]

On 01/06/2015 11:32 PM, Jakub Hrozek wrote:
> On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying
> > to track down all possible issues.
> >
> > Also, we realized that we were running in a bit of a bad state - the primary
> > ldap server was not available, but the backup was.
> >
> > Some logs:
> >
> > General question, is this bad?:
> > (Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done]
> > (0x0040): Failed to retrieve users
>
> This can be caused by many things, we neer more context..in general, the
> LDAP search has failed and SSSD would fall back to cached entries.

Okay, appears to be a simple "unknown user" type of response:

(Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
Got request for [4097][1][name=contracts-grants]
(Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [sdap_get_users_done] (0x0040):
Failed to retrieve users

contracts-grants is not in LDAP.
> > see that fairly frequently.
> >
> > Trouble:
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > failed.
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > (0x0020): sdap_async_connect_call request failed.
> > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [resolv_gethostbyname_done]
> > (0x0040): querying hosts database failed [5]: Input/output error
> > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [fo_resolve_service_done]
> > (0x0020): Failed to resolve server 'server.com': Timeout while contacting
> > DNS servers
> > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [be_resolve_server_process]
> > (0x0080): Couldn't resolve server (server.com), resolver returned (5)
>
> This seems like the core issue, can you resolve server.com from outside
> SSSD (with dig, maybe) ?

In general, yes.  But it seems that some kind of load/network issue caused a
temporary failure.  We've since added entries to /etc/hosts to try to prevent
this from happening again.
> > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]]
> > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > failed.
> > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > (0x0020): sdap_async_connect_call request failed.
> > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [fo_resolve_service_send]
> > (0x0020): No available servers for service 'LDAP'
> > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_id_op_connect_done]
> > (0x0020): Failed to connect, going offline (5 [Input/output error])
> > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> > Going offline. Running callbacks.
>
> Here SSSD goes offline and the front end would switch to using the
> cache.
> > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]] [get_single_value_as_string]
> > (0x0080): More than one value found.
> > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]]
> > [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> > (Tue Jan  6 22:33:14 2015) [sssd[be[default]]] [get_single_value_as_string]
> > (0x0080): More than one value found.
>
> This is weird as well, here SSSD is complaining that defaultNamingContext
> attribute of rootDSE contains multiple values. But I don't see SSSD grabbing
> the rootDSE anywhere at all..what log level did you use?

Log level 3
> You can read the rootDSE manually using:
> ldapsearch -x -H ldap://server.com -s base -b "" defaultNamingContext

# extended LDIF
#
# LDAPv3
# base <> with scope baseObject
# filter: (objectclass=*)
# requesting: defaultNamingContext
#

#
dn:

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1

I've now added a defaultnamingcontext.

[Lukas Slebodnik]

On (08/01/15 09:31), Orion Poplawski wrote:
> On 01/06/2015 11:32 PM, Jakub Hrozek wrote:
> > On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying
> > > to track down all possible issues.
> > >
> > > Also, we realized that we were running in a bit of a bad state - the primary
> > > ldap server was not available, but the backup was.
> > >
> > > Some logs:
> > >
> > > General question, is this bad?:
> > > (Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done]
> > > (0x0040): Failed to retrieve users
> >
> > This can be caused by many things, we neer more context..in general, the
> > LDAP search has failed and SSSD would fall back to cached entries.
>
> Okay, appears to be a simple "unknown user" type of response:
>
> (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
> Got request for [4097][1][name=contracts-grants]
> (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [sdap_get_users_done] (0x0040):
> Failed to retrieve users
>
> contracts-grants is not in LDAP.

You can filter request for non-LDAP users/groups in nss section of sssd.conf

man sssd.conf -> filter_users, filter_groups

LS

[Orion Poplawski]

On 01/08/2015 10:18 AM, Lukas Slebodnik wrote:
> On (08/01/15 09:31), Orion Poplawski wrote:
> > contracts-grants is not in LDAP.
>
> You can filter request for non-LDAP users/groups in nss section of sssd.conf
>
> man sssd.conf -> filter_users, filter_groups

Thanks, but I'm wondering why that user is even attempted to be looked up in
the first place - it's an email aliases.

I'm also seeing requests for the "postfix" user in sss, which is interesting
since it is in /etc/passwd, /etc/group.  Perhaps looking up supplementary
group info?

[Jakub Hrozek]

On Thu, Jan 08, 2015 at 11:46:55AM -0700, Orion Poplawski wrote:
> On 01/08/2015 10:18 AM, Lukas Slebodnik wrote:
> > On (08/01/15 09:31), Orion Poplawski wrote:
> > > contracts-grants is not in LDAP.
> >
> > You can filter request for non-LDAP users/groups in nss section of sssd.conf
> >
> > man sssd.conf -> filter_users, filter_groups
>
> Thanks, but I'm wondering why that user is even attempted to be looked up in
> the first place - it's an email aliases.

Is the domain part of the e-mail address same as the sssd domain name
perchance?
> I'm also seeing requests for the "postfix" user in sss, which is interesting
> since it is in /etc/passwd, /etc/group.  Perhaps looking up supplementary
> group info?

yes, initgroups(3) always cycles through all databases.

This is a prime candidate for adding into filter_users -- I filter out
pulse-rt and root on my laptop.

[Jakub Hrozek]

On Thu, Jan 08, 2015 at 09:31:16AM -0700, Orion Poplawski wrote:
> On 01/06/2015 11:32 PM, Jakub Hrozek wrote:
> > On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying
> > > to track down all possible issues.
> > >
> > > Also, we realized that we were running in a bit of a bad state - the primary
> > > ldap server was not available, but the backup was.
> > >
> > > Some logs:
> > >
> > > General question, is this bad?:
> > > (Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done]
> > > (0x0040): Failed to retrieve users
> >
> > This can be caused by many things, we neer more context..in general, the
> > LDAP search has failed and SSSD would fall back to cached entries.
>
> Okay, appears to be a simple "unknown user" type of response:
>
> (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
> Got request for [4097][1][name=contracts-grants]
> (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [sdap_get_users_done] (0x0040):
> Failed to retrieve users
>
> contracts-grants is not in LDAP.
> > > see that fairly frequently.
> > >
> > > Trouble:
> > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > > failed.
> > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > (0x0020): sdap_async_connect_call request failed.
> > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [resolv_gethostbyname_done]
> > > (0x0040): querying hosts database failed [5]: Input/output error
> > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [fo_resolve_service_done]
> > > (0x0020): Failed to resolve server 'server.com': Timeout while contacting
> > > DNS servers
> > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [be_resolve_server_process]
> > > (0x0080): Couldn't resolve server (server.com), resolver returned (5)
> >
> > This seems like the core issue, can you resolve server.com from outside
> > SSSD (with dig, maybe) ?
>
> In general, yes.  But it seems that some kind of load/network issue caused a
> temporary failure.  We've since added entries to /etc/hosts to try to prevent
> this from happening again.
> > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]]
> > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > > failed.
> > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > (0x0020): sdap_async_connect_call request failed.
> > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [fo_resolve_service_send]
> > > (0x0020): No available servers for service 'LDAP'
> > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_id_op_connect_done]
> > > (0x0020): Failed to connect, going offline (5 [Input/output error])
> > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> > > Going offline. Running callbacks.
> >
> > Here SSSD goes offline and the front end would switch to using the
> > cache.
> > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > (0x0080): More than one value found.
> > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]]
> > > [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> > > (Tue Jan  6 22:33:14 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > (0x0080): More than one value found.
> >
> > This is weird as well, here SSSD is complaining that defaultNamingContext
> > attribute of rootDSE contains multiple values. But I don't see SSSD grabbing
> > the rootDSE anywhere at all..what log level did you use?
>
> Log level 3
> > You can read the rootDSE manually using:
> > ldapsearch -x -H ldap://server.com -s base -b "" defaultNamingContext
>
> # extended LDIF
> #
> # LDAPv3
> # base <> with scope baseObject
> # filter: (objectclass=*)
> # requesting: defaultNamingContext
> #
>
> #
> dn:
>
> # search result
> search: 2
> result: 0 Success
>
> # numResponses: 2
> # numEntries: 1
>
> I've now added a defaultnamingcontext.

Did it cause any difference?

I wouldn't expect a missing defaultNamingContext to be fatal for SSSD..

[Orion Poplawski]

On 01/08/2015 11:54 AM, Jakub Hrozek wrote:
> On Thu, Jan 08, 2015 at 09:31:16AM -0700, Orion Poplawski wrote:
> > On 01/06/2015 11:32 PM, Jakub Hrozek wrote:
> > > On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> > > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > > (0x0080): More than one value found.
> > > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]]
> > > > [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> > > > (Tue Jan  6 22:33:14 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > > (0x0080): More than one value found.
> > >
> > > This is weird as well, here SSSD is complaining that defaultNamingContext
> > > attribute of rootDSE contains multiple values. But I don't see SSSD grabbing
> > > the rootDSE anywhere at all..what log level did you use?
> >
> > Log level 3
> > > You can read the rootDSE manually using:
> > > ldapsearch -x -H ldap://server.com -s base -b "" defaultNamingContext
> >
> > # extended LDIF
> > #
> > # LDAPv3
> > # base <> with scope baseObject
> > # filter: (objectclass=*)
> > # requesting: defaultNamingContext
> > #
> >
> > #
> > dn:
> >
> > # search result
> > search: 2
> > result: 0 Success
> >
> > # numResponses: 2
> > # numEntries: 1
> >
> > I've now added a defaultnamingcontext.
>
> Did it cause any difference?
>
> I wouldn't expect a missing defaultNamingContext to be fatal for SSSD..

It got rid of the debug messages complaining about it :)

[Lukas Slebodnik]

On (08/01/15 19:54), Jakub Hrozek wrote:
> On Thu, Jan 08, 2015 at 09:31:16AM -0700, Orion Poplawski wrote:
> > On 01/06/2015 11:32 PM, Jakub Hrozek wrote:
> > > On Tue, Jan 06, 2015 at 05:06:39PM -0700, Orion Poplawski wrote:
> > > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying
> > > > to track down all possible issues.
> > > >
> > > > Also, we realized that we were running in a bit of a bad state - the primary
> > > > ldap server was not available, but the backup was.
> > > >
> > > > Some logs:
> > > >
> > > > General question, is this bad?:
> > > > (Tue Jan  6 23:17:43 2015) [sssd[be[default]]] [sdap_get_users_done]
> > > > (0x0040): Failed to retrieve users
> > >
> > > This can be caused by many things, we neer more context..in general, the
> > > LDAP search has failed and SSSD would fall back to cached entries.
> >
> > Okay, appears to be a simple "unknown user" type of response:
> >
> > (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
> > Got request for [4097][1][name=contracts-grants]
> > (Thu Jan  8 15:50:47 2015) [sssd[be[default]]] [sdap_get_users_done] (0x0040):
> > Failed to retrieve users
> >
> > contracts-grants is not in LDAP.
> > > > see that fairly frequently.
> > > >
> > > > Trouble:
> > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > > > failed.
> > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > > (0x0020): sdap_async_connect_call request failed.
> > > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [resolv_gethostbyname_done]
> > > > (0x0040): querying hosts database failed [5]: Input/output error
> > > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [fo_resolve_service_done]
> > > > (0x0020): Failed to resolve server 'server.com': Timeout while contacting
> > > > DNS servers
> > > > (Tue Jan  6 22:30:36 2015) [sssd[be[default]]] [be_resolve_server_process]
> > > > (0x0080): Couldn't resolve server (server.com), resolver returned (5)
> > >
> > > This seems like the core issue, can you resolve server.com from outside
> > > SSSD (with dig, maybe) ?
> >
> > In general, yes.  But it seems that some kind of load/network issue caused a
> > temporary failure.  We've since added entries to /etc/hosts to try to prevent
> > this from happening again.
> > > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]]
> > > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request
> > > > failed.
> > > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > > (0x0020): sdap_async_connect_call request failed.
> > > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [fo_resolve_service_send]
> > > > (0x0020): No available servers for service 'LDAP'
> > > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [sdap_id_op_connect_done]
> > > > (0x0020): Failed to connect, going offline (5 [Input/output error])
> > > > (Tue Jan  6 22:30:45 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
> > > > Going offline. Running callbacks.
> > >
> > > Here SSSD goes offline and the front end would switch to using the
> > > cache.
> > > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > > (0x0080): More than one value found.
> > > > (Tue Jan  6 22:33:08 2015) [sssd[be[default]]]
> > > > [sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
> > > > (Tue Jan  6 22:33:14 2015) [sssd[be[default]]] [get_single_value_as_string]
> > > > (0x0080): More than one value found.
> > >
> > > This is weird as well, here SSSD is complaining that defaultNamingContext
> > > attribute of rootDSE contains multiple values. But I don't see SSSD grabbing
> > > the rootDSE anywhere at all..what log level did you use?
> >
> > Log level 3
> > > You can read the rootDSE manually using:
> > > ldapsearch -x -H ldap://server.com -s base -b "" defaultNamingContext
> >
> > # extended LDIF
> > #
> > # LDAPv3
> > # base <> with scope baseObject
> > # filter: (objectclass=*)
> > # requesting: defaultNamingContext
> > #
> >
> > #
> > dn:
> >
> > # search result
> > search: 2
> > result: 0 Success
> >
> > # numResponses: 2
> > # numEntries: 1
> >
> > I've now added a defaultnamingcontext.
>
> Did it cause any difference?
>
> I wouldn't expect a missing defaultNamingContext to be fatal for SSSD..

Some LDAP servers use "defaultNamingContext" other "namingContexts".
SSSD uses available one.

LS

[Orion Poplawski]

On 01/08/2015 12:24 PM, Lukas Slebodnik wrote:
> Some LDAP servers use "defaultNamingContext" other "namingContexts".
> SSSD uses available one.
>
> LS
> _______________________________________________

Ah, that may have been it - without a defaultnamingcontext, there are two
namingcontexts returned.

[Orion Poplawski]

On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> track down all possible issues.

Some updated logs with debug_level=4

Looks like some hiccups again overnight.  What seem odd here is that the
service is maked as working, but then also failed?

(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [acctinfo_callback] (0x0100):
Request processed. Returned 0,0,Success
(Thu Jan  8 08:45:24 2015) [sssd[be[default]]] [acctinfo_callback] (0x0100):
Request processed. Returned 0,0,Success
(Thu Jan  8 08:45:25 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:45:25 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:45:25 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [sdap_pam_auth_done] (0x0100):
Password successfully cached for XXX
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Backend returned: (0, 0, <NULL>) [Success]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sending result [0][default]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sent result [0][default]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_resolve_server_process]
(0x0040): The fail over cycled through all available servers
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_run_offline_cb] (0x0080):
Going offline. Running callbacks.
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Backend returned: (1, 9, <NULL>) [Provider is Offline
(Authentication service cannot retrieve authentication info)]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sending result [9][default]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sent result [9][default]
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:45:31 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:45:33 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:45:33 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
Got request for [3][1][name=XXX]
(Thu Jan  8 08:45:33 2015) [sssd[be[default]]] [be_get_account_info] (0x0100):
Got request for [3][1][name=XXX]
(Thu Jan  8 08:45:33 2015) [sssd[be[default]]] [acctinfo_callback] (0x0100):
Request processed. Returned 1,11,Offline

We're finally working again:

(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [get_single_value_as_string]
(0x0080): More than one value found.
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]]
[sdap_set_config_options_with_rootdse] (0x0020): get_naming_context failed.
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [sdap_cli_auth_step] (0x0100):
expire timeout is 900
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [sdap_attrs_get_sid_str]
(0x0080): No [objectSID] attribute while id-mapping. [0][Success]
(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [acctinfo_callback] (0x0100):
Request processed. Returned 0,0,Success

(Thu Jan  8 08:46:51 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [sdap_pam_auth_done] (0x0100):
Password successfully cached for XXX
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Backend returned: (0, 0, <NULL>) [Success]
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sending result [0][default]
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [be_pam_handler_callback]
(0x0100): Sent result [0][default]

(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 636 of server 'server.com' as 'working'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'server.com' as 'working'
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=XXX,ou=People,dc=server,dc=com
(Thu Jan  8 08:46:52 2015) [sssd[be[default]]] [sdap_pam_auth_done] (0x0100):
Password successfully cached for XXX

[Orion Poplawski]

On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> track down all possible issues.
>
> Also, we realized that we were running in a bit of a bad state - the primary
> ldap server was not available, but the backup was.
> Trouble:
> (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> (0x0020): sdap_async_connect_call request failed.

I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
sssd's handling of the ldap connection is not ideal.

[Jakub Hrozek]

On Wed, Jan 21, 2015 at 11:22:48AM -0700, Orion Poplawski wrote:
> On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> > track down all possible issues.
> >
> > Also, we realized that we were running in a bit of a bad state - the primary
> > ldap server was not available, but the backup was.
> > Trouble:
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > (0x0020): sdap_async_connect_call request failed.
>
> I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
> sssd's handling of the ldap connection is not ideal.

Thank you.

[Lukas Slebodnik]

On (21/01/15 11:22), Orion Poplawski wrote:
> On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> > track down all possible issues.
> >
> > Also, we realized that we were running in a bit of a bad state - the primary
> > ldap server was not available, but the backup was.
> > Trouble:
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > (0x0020): sdap_async_connect_call request failed.
>
> I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
> sssd's handling of the ldap connection is not ideal.

I checked strace log file and I can confirm you are right.
But I have no idea how to reproduce or fix it.
Output from strace is not sufficient.

We would need to see sssd log files with high debug_level.
You mentined the most problematic part of VPS is I/0.
So increasing debug_level can just complicate situation.

I can just give you an advice about *sync calls you mentioned in ticket.

It is not visible in strace log but fdatasync() and msync() are used on file
descriptor of sssd cache (/var/lib/sss/db/cache_*.ldb. They are used in ldb/tdb
for transactions.

If you do not need offline authentication you can mount tmpfs to directory
/var/lib/sss/db/.

tmpfs   /var/lib/sss/db/ tmpfs size=300M,mode=0700,noauto,rootcontext=system_u:object_r:sssd_var_lib_t:s0 0 0

LS

[Orion Poplawski]

On 01/22/2015 09:00 AM, Lukas Slebodnik wrote:
> On (21/01/15 11:22), Orion Poplawski wrote:
> > On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> > > track down all possible issues.
> > >
> > > Also, we realized that we were running in a bit of a bad state - the primary
> > > ldap server was not available, but the backup was.
> > > Trouble:
> > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > (0x0020): sdap_async_connect_call request failed.
> >
> > I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
> > sssd's handling of the ldap connection is not ideal.
>
> I checked strace log file and I can confirm you are right.
> But I have no idea how to reproduce or fix it.
> Output from strace is not sufficient.
>
> We would need to see sssd log files with high debug_level.
> You mentined the most problematic part of VPS is I/0.
> So increasing debug_level can just complicate situation.

I'll see what I can do.
> I can just give you an advice about *sync calls you mentioned in ticket.
>
> It is not visible in strace log but fdatasync() and msync() are used on file
> descriptor of sssd cache (/var/lib/sss/db/cache_*.ldb. They are used in ldb/tdb
> for transactions.
>
> If you do not need offline authentication you can mount tmpfs to directory
> /var/lib/sss/db/.
>
> tmpfs   /var/lib/sss/db/ tmpfs size=300M,mode=0700,noauto,rootcontext=system_u:object_r:sssd_var_lib_t:s0 0 0

That is a good idea, thanks.  Offline auth should work though unless the
machine got rebooted, correct?

[Lukas Slebodnik]

On (22/01/15 12:11), Orion Poplawski wrote:
> On 01/22/2015 09:00 AM, Lukas Slebodnik wrote:
> > On (21/01/15 11:22), Orion Poplawski wrote:
> > > On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> > > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> > > > track down all possible issues.
> > > >
> > > > Also, we realized that we were running in a bit of a bad state - the primary
> > > > ldap server was not available, but the backup was.
> > > > Trouble:
> > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > > (0x0020): sdap_async_connect_call request failed.
> > >
> > > I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
> > > sssd's handling of the ldap connection is not ideal.
> >
> > I checked strace log file and I can confirm you are right.
> > But I have no idea how to reproduce or fix it.
> > Output from strace is not sufficient.
> >
> > We would need to see sssd log files with high debug_level.
> > You mentined the most problematic part of VPS is I/0.
> > So increasing debug_level can just complicate situation.
>
> I'll see what I can do.
> > I can just give you an advice about *sync calls you mentioned in ticket.
> >
> > It is not visible in strace log but fdatasync() and msync() are used on file
> > descriptor of sssd cache (/var/lib/sss/db/cache_*.ldb. They are used in ldb/tdb
> > for transactions.
> >
> > If you do not need offline authentication you can mount tmpfs to directory
> > /var/lib/sss/db/.
> >
> > tmpfs   /var/lib/sss/db/ tmpfs size=300M,mode=0700,noauto,rootcontext=system_u:object_r:sssd_var_lib_t:s0 0 0
>
> That is a good idea, thanks.  Offline auth should work though unless the
> machine got rebooted, correct?

Yes,
I have correlation in my mind between offline authentication and use case on
laptop and it is usual to reboot laptop.

To be precise offline authentication(pam) is not enabled by default
    @see man sssd.conf -> cache_credentials

LS

[Jakub Hrozek]

On Thu, Jan 22, 2015 at 09:05:40PM +0100, Lukas Slebodnik wrote:
> On (22/01/15 12:11), Orion Poplawski wrote:
> > On 01/22/2015 09:00 AM, Lukas Slebodnik wrote:
> > > On (21/01/15 11:22), Orion Poplawski wrote:
> > > > On 01/06/2015 05:06 PM, Orion Poplawski wrote:
> > > > > We're having some trouble with sssd on centos 7 under load on a VPS. 389ds
> > > > > ldap server for id/auth.  Part may be an issue with the VPS, but I'm trying to
> > > > > track down all possible issues.
> > > > >
> > > > > Also, we realized that we were running in a bit of a bad state - the primary
> > > > > ldap server was not available, but the backup was.
> > > > > Trouble:
> > > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]]
> > > > > [sss_ldap_init_sys_connect_done] (0x0020): sdap_async_sys_connect request failed.
> > > > > (Tue Jan  6 22:30:31 2015) [sssd[be[default]]] [sdap_sys_connect_done]
> > > > > (0x0020): sdap_async_connect_call request failed.
> > > >
> > > > I ended up filing https://fedorahosted.org/sssd/ticket/2562 as it seems like
> > > > sssd's handling of the ldap connection is not ideal.
> > >
> > > I checked strace log file and I can confirm you are right.
> > > But I have no idea how to reproduce or fix it.
> > > Output from strace is not sufficient.
> > >
> > > We would need to see sssd log files with high debug_level.
> > > You mentined the most problematic part of VPS is I/0.
> > > So increasing debug_level can just complicate situation.
> >
> > I'll see what I can do.
> > > I can just give you an advice about *sync calls you mentioned in ticket.
> > >
> > > It is not visible in strace log but fdatasync() and msync() are used on file
> > > descriptor of sssd cache (/var/lib/sss/db/cache_*.ldb. They are used in ldb/tdb
> > > for transactions.
> > >
> > > If you do not need offline authentication you can mount tmpfs to directory
> > > /var/lib/sss/db/.
> > >
> > > tmpfs   /var/lib/sss/db/ tmpfs size=300M,mode=0700,noauto,rootcontext=system_u:object_r:sssd_var_lib_t:s0 0 0
> >
> > That is a good idea, thanks.  Offline auth should work though unless the
> > machine got rebooted, correct?
>
> Yes,
> I have correlation in my mind between offline authentication and use case on
> laptop and it is usual to reboot laptop.
>
> To be precise offline authentication(pam) is not enabled by default
>     @see man sssd.conf -> cache_credentials

Please note the cache must be primed with the password hash while online
before you can authenticate offline :-)

[Orion Poplawski]

On 01/22/2015 09:00 AM, Lukas Slebodnik wrote:
> We would need to see sssd log files with high debug_level.
> You mentined the most problematic part of VPS is I/0.
> So increasing debug_level can just complicate situation.

I might be able to use the same tmpfs trick for the debug logs - what
debug_level do you think you would need?

[Lukas Slebodnik]

On (22/01/15 12:20), Orion Poplawski wrote:
> On 01/22/2015 09:00 AM, Lukas Slebodnik wrote:
> > We would need to see sssd log files with high debug_level.
> > You mentined the most problematic part of VPS is I/0.
> > So increasing debug_level can just complicate situation.
>
> I might be able to use the same tmpfs trick for the debug logs - what
> debug_level do you think you would need?

The best would be full 0xfff0. It would be good to se strace output with
timestamp as well. So we can compare them.

LS