On 04/15/2013 05:23 PM, Jakub Hrozek wrote:
On Mon, Apr 15, 2013 at 04:47:15PM +0200, steve wrote:
> On 04/15/2013 01:59 PM, Ondrej Kos wrote:
>> On 04/15/2013 01:29 PM, steve wrote:
>>> On 04/15/2013 12:36 PM, Jakub Hrozek wrote:
>>>> On Mon, Apr 15, 2013 at 12:17:33PM +0200, steve wrote:
>>>>> On 04/15/2013 11:33 AM, Jakub Hrozek wrote:
>>>>>> Have you been able to check what kind of searches (with wireshark
or
>>>>>> similar
>>>>>> or even just looking at the debug logs) sssd is doing?
>>>>>> There should be
>>>>>> one search for users and one for groups every 300 seconds by
default
>>>>>> (can be overriden with ldap_enumeration_refresh_timeout).
>>>>>>
>>>>>> Also how many users/groups do you have on the server?
>>>>>>
>>>>> Hi
>>>>> Test setup with 2 users and 2 groups. The ldap server (Samba4 AD) is
>>>>> flooded with requests every second. I attach small bits from each
>>>>> log. If you coud have a look that would be great.
>>>>>
>>>> Thanks for the logs. I suspect that what happens is that the sssd_be
>>>> crashes or is restarted for some reason and after being
>>>> respawned starts
>>>> another enumeration which is why you are seeing so many searches.
>>>>
>>>> As a matter of fact, there is a patch on the list to fix a potential
>>>> crash when enumerating. Which version are you running? Maybe you're
>>>> hitting that exact problem.
>>>>
>>>>> TIA
>>>>> Steve
>>>>>
>>>> [snip]
>>>>
>>>>> sssd_default.log
>>>> [snip]
>>>>> (Mon Apr 15 12:00:43 2013) [sssd[be[default]]] [dp_get_options]
>>>>> (0x0400): Option ldap_dns_service_name has value ldap
>>>>> (Mon Apr 15 12:00:43 2013) [sssd[be[default]]] [dp_get_options]
>>>>> (0x0400): Option ldap_krb5_ticket_lifetime has value 86400
>>>> Is there something more in the log? The part you pasted pretty much
>>>> describes the option being loaded.
>>> Hi
>>> The log got bounced because it was too big. I've put it here:
>>>
https://dl.dropboxusercontent.com/u/45150875/sssd_default.log
>>>>> sss.log
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [client_registration] (0x0100):
>>>>> Received ID registration: (pam,1)
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [mark_service_as_started]
>>>>> (0x0200): Marking pam as started.
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [sbus_server_init_new_connection]
>>>>> (0x0200): Entering.
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [sbus_server_init_new_connection]
>>>>> (0x0200): Adding connection 0x8708c60.
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [sbus_init_connection] (0x0200):
>>>>> Adding connection 8708C60
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [sbus_server_init_new_connection]
>>>>> (0x0200): Got a connection
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [monitor_service_init] (0x0400):
>>>>> Initializing D-BUS Service
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [client_registration] (0x0100):
>>>>> Received ID registration: (nss,1)
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [mark_service_as_started]
>>>>> (0x0200): Marking nss as started.
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [mark_service_as_started]
>>>>> (0x0400): SSSD is initialized, terminating parent process
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [sbus_dispatch] (0x0080):
>>>>> Connection is not open for dispatching.
>>>>> (Mon Apr 15 12:00:40 2013) [sssd] [mt_svc_exit_handler] (0x0040):
>>>>> Child [default] terminated with signal [6]
>>>> Here is some more evidence, signal [6] is SIGABRT so the back end
>>>> crashed.
>>>>
>>>> It's quite possible that you hit
>>>>
https://fedorahosted.org/sssd/ticket/1799,
>>>> if you could collect the backtrace then we would know for sure. We
>>>> already
>>>> have a patch for that problem and will include the fix in the shortly
>>>> upcoming
>>>> 1.9.5 release.
>>> Thanks. Our version is 1.9.4 on Ubuntu 12.10. Will gladly test anything
>>> on 1.9.5 and report back.
>>> Cheers,
>>> Steve
>>>
>> Hi Steve,
>>
>> Does ldapsearch against the configured server work? Because from
>> the provided logs, I see that there's issue with contacting it.
>>
>> [sdap_process_result] (0x0040): ldap_result error: [Can't contact
>> LDAP server]
>>
>>
> Hi
> Yes. ldapsearch is working. e.g.
>
> sudo ldapsearch -h doloresdc.dolores.site -b 'dc=dolores,dc=site'
> "(cn=steve2)" -Y GSSAPI
> SASL/GSSAPI authentication started
> SASL username: Administrator(a)DOLORES.SITE
> SASL SSF: 56
> SASL data security layer installed.
Ah, but here you are using a different SASL username than the SSSD, I
think. According to the config you sent earlier, you set the authid to
DOLORESDC$.
Can you also try kinit as this principal and then ldapsearch again,
please? That would get you very close to what the SSSD is doing.
You would do something like this (modulo different names in case I
mistyped):
kdestroy
kinit -k DOLORESDC$(a)DOLORES.SITE
ldapsearch -h doloresdc.dolores.site -b 'dc=dolores,dc=site'
"(cn=steve2)" -Y GSSAPI
Hi
OK.
steve@doloresdc:~$ sudo kdestroy
steve@doloresdc:~$ sudo kinit -k DOLORESDC$
steve@doloresdc:~$ sudo ldapsearch -h doloresdc.dolores.site -b
'dc=dolores,dc=site' "(cn=steve2)" -Y GSSAPI
SASL/GSSAPI authentication started
SASL username: DOLORESDC$(a)DOLORES.SITE
SASL SSF: 56
SASL data security layer installed.
# extended LDIF
#
# LDAPv3
# base <dc=dolores,dc=site> with scope subtree
# filter: (cn=steve2)
# requesting: ALL
#
# steve2, Users, dolores.site
dn: CN=steve2,CN=Users,DC=dolores,DC=site
cn: steve2
instanceType: 4
whenCreated: 20130415110516.0Z
uSNCreated: 3794
name: steve2
objectGUID:: jiXWdhBr6kWi1lB53iBxLQ==
badPwdCount: 0
codePage: 0
countryCode: 0
badPasswordTime: 0
lastLogoff: 0
lastLogon: 0
primaryGroupID: 513
objectSid:: AQUAAAAAAAUVAAAAVV34Nfc0pG0Q3HZqWgQAAA==
logonCount: 0
sAMAccountName: steve2
sAMAccountType: 805306368
userPrincipalName: steve2(a)dolores.site
objectCategory: CN=Person,CN=Schema,CN=Configuration,DC=dolores,DC=site
pwdLastSet: 130104975160000000
userAccountControl: 66048
accountExpires: 0
uidNumber: 3000024
gidNumber: 20513
unixHomeDirectory: /home/users/steve2
loginShell: /bin/bash
objectClass: top
objectClass: posixAccount
objectClass: person
objectClass: organizationalPerson
objectClass: user
profilePath: \\doloresdc\profiles\steve2
homeDrive: Z:
homeDirectory: \\doloresdc\users\steve2
whenChanged: 20130415110519.0Z
uSNChanged: 3800
memberOf: CN=staff,CN=Users,DC=dolores,DC=site
distinguishedName: CN=steve2,CN=Users,DC=dolores,DC=site
# search reference
ref: ldap://dolores.site/CN=Configuration,DC=dolores,DC=site
# search reference
ref: ldap://dolores.site/DC=DomainDnsZones,DC=dolores,DC=site
# search reference
ref: ldap://dolores.site/DC=ForestDnsZones,DC=dolores,DC=site
# search result
search: 4
result: 0 Success
# numResponses: 5
# numEntries: 1
# numReferences: 3
And the machine cache has this:
steve@doloresdc:~$ sudo klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: DOLORESDC$(a)DOLORES.SITE
Valid starting Expires Service principal
15/04/2013 18:21 16/04/2013 04:21 krbtgt/DOLORES.SITE(a)DOLORES.SITE
renew until 16/04/2013 18:21
15/04/2013 18:21 16/04/2013 04:21 ldap/doloresdc.dolores.site@
renew until 16/04/2013 18:21
15/04/2013 18:21 16/04/2013 04:21 ldap/doloresdc.dolores.site(a)DOLORES.SITE
renew until 16/04/2013 18:21
Also one thing I missed is that you are using IP address instead of
host
name in the config file, at least according to the log on dropbox. I would
recommend using hostnames with GSSAPI, sometimes the SASL library might
attempt to canonicalize the hostname and fail if it can't.
AD giving this
error:
ldb_wrap open of secrets.ldb
Terminating connection - 'LDAP_PROTOCOL_ERROR'
single_terminate: reason[LDAP_PROTOCOL_ERROR]
and sssd is still giving many of these:
steve@doloresdc:/var/log/sssd$ sudo cat sssd_default.log | grep "Can't"
(Mon Apr 15 16:58:11 2013) [sssd[be[default]]] [sdap_process_result]
(0x0040): ldap_result error: [Can't contact LDAP server]
(Mon Apr 15 16:58:21 2013) [sssd[be[default]]] [sdap_process_result]
(0x0040): ldap_result error: [Can't contact LDAP server]
Sorry. . .