9:16 p.m.
Just recently we're seeing some very strange behavior on our system.
Periodically we will see a sssd process start to have an ever greater
number of connections to our ldap server until the server runs out of
file descriptors. This seems to be happening with a particular user,
who is having trouble logging in at times, particularly with email
(dovecot). We see entries like the following on our sever:
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120
nentries=0 etime=0
[05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND
msgid=2
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
I don't yet have debug info from the sssd process. Any ideas from the
above?
Restarting the sssd process seems to clear things up for a while.
- Orion
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA/CoRA Division FAX: 303-415-9702
3380 Mitchell Lane orion(a)cora.nwra.com
Boulder, CO 80301 http://www.cora.nwra.com
4:14 a.m.
On 11/06/2014 04:16 AM, Orion Poplawski wrote:
Just recently we're seeing some very strange behavior on our
system.
Periodically we will see a sssd process start to have an ever greater
number of connections to our ldap server until the server runs out of
file descriptors. This seems to be happening with a particular user,
who is having trouble logging in at times, particularly with email
(dovecot). We see entries like the following on our sever:
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120
nentries=0 etime=0
[05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON
targetop=NOTFOUND msgid=2
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
I don't yet have debug info from the sssd process. Any ideas from the
above?
Restarting the sssd process seems to clear things up for a while.
- Orion
Try to reproduce the problem while using gdb to capture stack traces
every few seconds as in
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
Ideally, we can get some stack traces of the server during the time
between the BIND and the ABANDON
11:35 a.m.
On 11/06/2014 03:14 AM, Rich Megginson wrote:
Try to reproduce the problem while using gdb to capture stack traces
every few
seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
Ideally, we can get some stack traces of the server during the time between
the BIND and the ABANDON
Thanks, I'll give it a shot. The gdb command line is a little incorrect
though, I think you want:
gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply
all bt
full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` > stacktrace.`date
+%s`.txt 2>&1
- added % in date format, drop trailing ``
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
3:03 a.m.
On 11/06/2014 06:35 PM, Orion Poplawski wrote:
On 11/06/2014 03:14 AM, Rich Megginson wrote:
> Try to reproduce the problem while using gdb to capture stack traces every few
> seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
> Ideally, we can get some stack traces of the server during the time between
> the BIND and the ABANDON
Thanks, I'll give it a shot. The gdb command line is a little incorrect
though, I think you want:
gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply
all bt
full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` > stacktrace.`date
+%s`.txt 2>&1
- added % in date format, drop trailing ``
Thanks, wiki updated
12:59 p.m.
On 11/06/2014 10:35 AM, Orion Poplawski wrote:
On 11/06/2014 03:14 AM, Rich Megginson wrote:
> Try to reproduce the problem while using gdb to capture stack traces every few
> seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
> Ideally, we can get some stack traces of the server during the time between
> the BIND and the ABANDON
Thanks, I'll give it a shot. The gdb command line is a little incorrect
though, I think you want:
gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread apply
all bt
full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` > stacktrace.`date
+%s`.txt 2>&1
- added % in date format, drop trailing ``
gdb ended up aborting while trying to do the stack trace when the problem
occurred (https://bugzilla.redhat.com/show_bug.cgi?id=1162264) so I haven't
had any luck there.
It seems to be a problem with one of my servers only. I've shut it down and
the user can authenticate fine against our backup server. I tried restoring
from backup with bak2db but that didn't appear to help. Is there a more
restore from scratch procedure I should try next to see if it some kind of
corruption?
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
1:07 p.m.
On 11/10/2014 11:59 AM, Orion Poplawski wrote:
On 11/06/2014 10:35 AM, Orion Poplawski wrote:
> On 11/06/2014 03:14 AM, Rich Megginson wrote:
>> Try to reproduce the problem while using gdb to capture stack traces every few
>> seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
>> Ideally, we can get some stack traces of the server during the time between
>> the BIND and the ABANDON
>
> Thanks, I'll give it a shot. The gdb command line is a little incorrect
> though, I think you want:
>
> gdb -ex 'set confirm off' -ex 'set pagination off' -ex 'thread
apply all bt
> full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` >
stacktrace.`date
> +%s`.txt 2>&1
>
> - added % in date format, drop trailing ``
gdb ended up aborting while trying to do the stack trace when the problem
occurred (https://bugzilla.redhat.com/show_bug.cgi?id=1162264) so I haven't
had any luck there.
What platform are you using? Can you provide an example of the gdb output?
It seems to be a problem with one of my servers only. I've shut it down and
the user can authenticate fine against our backup server. I tried restoring
from backup with bak2db but that didn't appear to help. Is there a more
restore from scratch procedure I should try next to see if it some kind of
corruption?
I don't know. I'm not sure how db corruption could be causing this
issue. The best way to restore is to completely rebuild the database
e.g. db2ldif then ldif2db - then reinit all of your replicas.
2:58 p.m.
On 11/10/2014 12:07 PM, Rich Megginson wrote:
On 11/10/2014 11:59 AM, Orion Poplawski wrote:
> On 11/06/2014 10:35 AM, Orion Poplawski wrote:
>> On 11/06/2014 03:14 AM, Rich Megginson wrote:
>>> Try to reproduce the problem while using gdb to capture stack traces every
>>> few
>>> seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
>>> Ideally, we can get some stack traces of the server during the time between
>>> the BIND and the ABANDON
>>
>> Thanks, I'll give it a shot. The gdb command line is a little incorrect
>> though, I think you want:
>>
>> gdb -ex 'set confirm off' -ex 'set pagination off' -ex
'thread apply all bt
>> full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` >
stacktrace.`date
>> +%s`.txt 2>&1
>>
>> - added % in date format, drop trailing ``
> gdb ended up aborting while trying to do the stack trace when the problem
> occurred (https://bugzilla.redhat.com/show_bug.cgi?id=1162264) so I haven't
> had any luck there.
What platform are you using? Can you provide an example of the gdb output?
Scientific Linux 6.5
389-ds-base-1.2.11.32-1.el6.x86_64
gdb output is in the bug report, but basically:
../../gdb/linux-nat.c:1411: internal-error: linux_nat_post_attach_wait:
Assertion `pid == new_pid' failed.
>
> It seems to be a problem with one of my servers only. I've shut it down and
> the user can authenticate fine against our backup server. I tried restoring
> from backup with bak2db but that didn't appear to help. Is there a more
> restore from scratch procedure I should try next to see if it some kind of
> corruption?
I don't know. I'm not sure how db corruption could be causing this issue.
The best way to restore is to completely rebuild the database e.g. db2ldif
then ldif2db - then reinit all of your replicas.
So the "reinit all of your replicase" part sounds scary to me. Any
documentation for this process?
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
4:32 p.m.
On 11/06/2014 03:14 AM, Rich Megginson wrote:
On 11/06/2014 04:16 AM, Orion Poplawski wrote:
> Just recently we're seeing some very strange behavior on our system.
> Periodically we will see a sssd process start to have an ever greater number
> of connections to our ldap server until the server runs out of file
> descriptors. This seems to be happening with a particular user, who is
> having trouble logging in at times, particularly with email (dovecot). We
> see entries like the following on our sever:
>
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
> oid="1.3.6.1.4.1.1466.20037" name="startTLS"
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120
> nentries=0 etime=0
> [05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
> dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND
> msgid=2
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
>
> I don't yet have debug info from the sssd process. Any ideas from the above?
>
> Restarting the sssd process seems to clear things up for a while.
>
> - Orion
>
Try to reproduce the problem while using gdb to capture stack traces every few
seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
Ideally, we can get some stack traces of the server during the time between
the BIND and the ABANDON
If I catch the problem early enough I can still get a stack trace. A series
of them are in http://www.cora.nwra.com/~orion/ns-slapd-trace.tar.gz.
Anything useful there?
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
4:55 p.m.
On 11/10/2014 03:32 PM, Orion Poplawski wrote:
On 11/06/2014 03:14 AM, Rich Megginson wrote:
> On 11/06/2014 04:16 AM, Orion Poplawski wrote:
>> Just recently we're seeing some very strange behavior on our system.
>> Periodically we will see a sssd process start to have an ever greater number
>> of connections to our ldap server until the server runs out of file
>> descriptors. This seems to be happening with a particular user, who is
>> having trouble logging in at times, particularly with email (dovecot). We
>> see entries like the following on our sever:
>>
>> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
>> oid="1.3.6.1.4.1.1466.20037" name="startTLS"
>> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120
>> nentries=0 etime=0
>> [05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
>> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
>> dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
>> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND
>> msgid=2
>> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
>> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
>>
>> I don't yet have debug info from the sssd process. Any ideas from the
above?
>>
>> Restarting the sssd process seems to clear things up for a while.
>>
>> - Orion
>>
> Try to reproduce the problem while using gdb to capture stack traces every few
> seconds as in http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
> Ideally, we can get some stack traces of the server during the time between
> the BIND and the ABANDON
If I catch the problem early enough I can still get a stack trace. A series
of them are in http://www.cora.nwra.com/~orion/ns-slapd-trace.tar.gz.
Anything useful there?
These traces show the server is almost entirely idle - not working on
client operations, not deadlocked or otherwise waiting on locks, not
waiting on I/O to complete. So either we're still not catching dirsrv
in the act, or dirsrv is not the problem.
6:58 p.m.
On 11/10/2014 05:44 PM, Paul Robert Marino wrote:
When did this start?
The reason I ask is I've noticed a lot of problems with RHEV since the
recent updates to nss and openssl to deal with the POODLE vulnerability.
Like what?
The workaround for a loot of them is to ensure minssf is set to a
value higher than 0.
I'm wondering if this might be something similar. In the past I had
never set that option because my LDAP database contained no password
and Kerberos was its own database so the risk was nominal. Now I find
at least for RHEV (ovirt) I'm suddenly forced to set it.
So if you run 389 in RHEV, you have to set minssf, and if you run the
same version of 389 on bare metal, you don't have to set minssf?
If this is not an accurate description of your problem, can you please
elaborate?
-- Sent from my HP Pre3
------------------------------------------------------------------------
On Nov 10, 2014 3:58 PM, Orion Poplawski <orion(a)cora.nwra.com> wrote:
On 11/10/2014 12:07 PM, Rich Megginson wrote:
> On 11/10/2014 11:59 AM, Orion Poplawski wrote:
>> On 11/06/2014 10:35 AM, Orion Poplawski wrote:
>>> On 11/06/2014 03:14 AM, Rich Megginson wrote:
>>>> Try to reproduce the problem while using gdb to capture stack
traces every
>>>> few
>>>> seconds as in
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
>>>> Ideally, we can get some stack traces of the server during the
time between
>>>> the BIND and the ABANDON
>>>
>>> Thanks, I'll give it a shot. The gdb command line is a little
incorrect
>>> though, I think you want:
>>>
>>> gdb -ex 'set confirm off' -ex 'set pagination off' -ex
'thread
apply all bt
>>> full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` >
stacktrace.`date
>>> +%s`.txt 2>&1
>>>
>>> - added % in date format, drop trailing ``
>> gdb ended up aborting while trying to do the stack trace when the
problem
>> occurred (https://bugzilla.redhat.com/show_bug.cgi?id=1162264) so I
haven't
>> had any luck there.
>
> What platform are you using? Can you provide an example of the gdb
output?
>
Scientific Linux 6.5
389-ds-base-1.2.11.32-1.el6.x86_64
gdb output is in the bug report, but basically:
../../gdb/linux-nat.c:1411: internal-error: linux_nat_post_attach_wait:
Assertion `pid == new_pid' failed.
Hmm - never seen this before.
>>
>> It seems to be a problem with one of my servers only. I've shut it
down and
>> the user can authenticate fine against our backup server. I tried
restoring
>> from backup with bak2db but that didn't appear to help. Is there a more
>> restore from scratch procedure I should try next to see if it some
kind of
>> corruption?
>
> I don't know. I'm not sure how db corruption could be causing this
issue.
> The best way to restore is to completely rebuild the database e.g.
db2ldif
> then ldif2db - then reinit all of your replicas.
So the "reinit all of your replicase" part sounds scary to me. Any
documentation for this process?
Why is it scary? It's just the regular replica initialization process.
There's no trick, nothing fancy, no extra documentation. The thing to
realize is that a replica reinit does a database reinit, from scratch.
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
--
389 users mailing list
389-users(a)lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
389-users(a)lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users
9:39 a.m.
take a look at bugzilla ticket
https://bugzilla.redhat.com/show_bug.cgi?id=1156577
by the way I was incorrect about it being POODLE update related It
turns out there has been a change to the SASL GSSAPI module that has
caused some chaos.
On Mon, Nov 10, 2014 at 8:16 PM, Paul Robert Marino <prmarino1(a)gmail.com> wrote:
No that's not it.
If RHEVM (manager) is using 389 server in In "RHDS" mode for authentication
for its web portal that's where the issue pops up.
When I get back to the office in the morning I'll spend a link to a bugzilla
ticket about it which on ovirt 3.5 which I discover earlier tonight also
applies to RHEV (ovirt) 3.3 and 3.4
-- Sent from my HP Pre3
________________________________
On Nov 10, 2014 7:58 PM, Rich Megginson <rmeggins(a)redhat.com> wrote:
On 11/10/2014 05:44 PM, Paul Robert Marino wrote:
When did this start?
The reason I ask is I've noticed a lot of problems with RHEV since the
recent updates to nss and openssl to deal with the POODLE vulnerability.
Like what?
The workaround for a loot of them is to ensure minssf is set to a value
higher than 0.
I'm wondering if this might be something similar. In the past I had never
set that option because my LDAP database contained no password and Kerberos
was its own database so the risk was nominal. Now I find at least for RHEV
(ovirt) I'm suddenly forced to set it.
So if you run 389 in RHEV, you have to set minssf, and if you run the same
version of 389 on bare metal, you don't have to set minssf?
If this is not an accurate description of your problem, can you please
elaborate?
-- Sent from my HP Pre3
________________________________
On Nov 10, 2014 3:58 PM, Orion Poplawski <orion(a)cora.nwra.com> wrote:
On 11/10/2014 12:07 PM, Rich Megginson wrote:
> On 11/10/2014 11:59 AM, Orion Poplawski wrote:
>> On 11/06/2014 10:35 AM, Orion Poplawski wrote:
>>> On 11/06/2014 03:14 AM, Rich Megginson wrote:
>>>> Try to reproduce the problem while using gdb to capture stack traces
>>>> every
>>>> few
>>>> seconds as in
>>>> http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
>>>> Ideally, we can get some stack traces of the server during the time
>>>> between
>>>> the BIND and the ABANDON
>>>
>>> Thanks, I'll give it a shot. The gdb command line is a little incorrect
>>> though, I think you want:
>>>
>>> gdb -ex 'set confirm off' -ex 'set pagination off' -ex
'thread apply all
>>> bt
>>> full' -ex 'quit' /usr/sbin/ns-slapd `pidof ns-slapd` >
stacktrace.`date
>>> +%s`.txt 2>&1
>>>
>>> - added % in date format, drop trailing ``
>> gdb ended up aborting while trying to do the stack trace when the problem
>> occurred (https://bugzilla.redhat.com/show_bug.cgi?id=1162264) so I
>> haven't
>> had any luck there.
>
> What platform are you using? Can you provide an example of the gdb output?
>
Scientific Linux 6.5
389-ds-base-1.2.11.32-1.el6.x86_64
gdb output is in the bug report, but basically:
../../gdb/linux-nat.c:1411: internal-error: linux_nat_post_attach_wait:
Assertion `pid == new_pid' failed.
Hmm - never seen this before.
>>
>> It seems to be a problem with one of my servers only. I've shut it down
>> and
>> the user can authenticate fine against our backup server. I tried
>> restoring
>> from backup with bak2db but that didn't appear to help. Is there a more
>> restore from scratch procedure I should try next to see if it some kind
>> of
>> corruption?
>
> I don't know. I'm not sure how db corruption could be causing this issue.
> The best way to restore is to completely rebuild the database e.g. db2ldif
> then ldif2db - then reinit all of your replicas.
So the "reinit all of your replicase" part sounds scary to me. Any
documentation for this process?
Why is it scary? It's just the regular replica initialization process.
There's no trick, nothing fancy, no extra documentation. The thing to
realize is that a replica reinit does a database reinit, from scratch.
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
--
389 users mailing list
389-users(a)lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
389-users(a)lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users
6:01 p.m.
On 11/05/2014 08:16 PM, Orion Poplawski wrote:
Just recently we're seeing some very strange behavior on our
system.
Periodically we will see a sssd process start to have an ever greater number
of connections to our ldap server until the server runs out of file
descriptors. This seems to be happening with a particular user, who is having
trouble logging in at times, particularly with email (dovecot). We see
entries like the following on our sever:
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120 nentries=0
etime=0
[05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND msgid=2
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
I don't yet have debug info from the sssd process. Any ideas from the above?
Restarting the sssd process seems to clear things up for a while.
- Orion
I tried turning on some error log tracing to see if that helps:
[11/Nov/2014:16:33:55 -0700] - new connection on 66
[11/Nov/2014:16:33:55 -0700] - => ids_sasl_server_new (SERVER.DOMAIN.com)
[11/Nov/2014:16:33:55 -0700] - ids_sasl_getopt: plugin= option=log_level
[11/Nov/2014:16:33:55 -0700] - ids_sasl_getopt: plugin= option=auto_transition
[11/Nov/2014:16:33:55 -0700] - <= ids_sasl_server_new
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - activity on 66r
[11/Nov/2014:16:33:55 -0700] - read activity on 66
[11/Nov/2014:16:33:55 -0700] - add_pb
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - get_pb
[11/Nov/2014:16:33:55 -0700] - conn 2843 activity level = 0
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_in_use
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_in_use: 0
[11/Nov/2014:16:33:55 -0700] - do_extended
[11/Nov/2014:16:33:55 -0700] - => get_ldapmessage_controls
[11/Nov/2014:16:33:55 -0700] - <= get_ldapmessage_controls no controls
[11/Nov/2014:16:33:55 -0700] - listener got signaled
[11/Nov/2014:16:33:55 -0700] - => send_ldap_result 0::Start TLS request
accepted.Server willing to negotiate SSL.
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_result
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - activity on 66r
[11/Nov/2014:16:33:55 -0700] - read activity on 66
[11/Nov/2014:16:33:55 -0700] - add_pb
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - get_pb
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit()
conn=0x9465f290, handle=8
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - do_bind
[11/Nov/2014:16:33:55 -0700] - listener got signaled
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - BIND dn="uid=USER,ou=People,dc=DOMAIN,dc=com"
method=128 version=3
[11/Nov/2014:16:33:55 -0700] - => get_ldapmessage_controls
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.2)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NOT FOUND)
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
1.3.6.1.4.1.42.2.27.8.5.1)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 1 (FOUND)
[11/Nov/2014:16:33:55 -0700] - <= get_ldapmessage_controls 1 controls
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.16)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NOT FOUND)
[11/Nov/2014:16:33:55 -0700] - do_bind: version 3 method 0x80 dn
uid=USER,ou=People,dc=DOMAIN,dc=com
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 401
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
preoperation plugin' #9 type 401
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.12)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NO CONTROLS)
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.18)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NO CONTROLS)
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=6
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=5
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => compute_limits: sizelimit=-1, timelimit=-1
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Account Usability Plugin' #1
type 403
[11/Nov/2014:16:33:55 -0700] account-usability-plugin - --> auc_pre_search
[11/Nov/2014:16:33:55 -0700] account-usability-plugin - <-- auc_pre_op
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'ACL preoperation' #2 type 403
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'deref' #4 type 403
[11/Nov/2014:16:33:55 -0700] deref-plugin - --> deref_pre_search
[11/Nov/2014:16:33:55 -0700] deref-plugin - <-- deref_pre_op
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 403
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
preoperation plugin' #9 type 403
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=0
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => find_entry_internal
(dn=uid=USER,ou=people,dc=DOMAIN,dc=com) lock 0
[11/Nov/2014:16:33:55 -0700] - => dn2entry_ext
"uid=USER,ou=people,dc=DOMAIN,dc=com"
[11/Nov/2014:16:33:55 -0700] - <= dn2entry_ext 7f7d300101a0
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal_dn found
(uid=USER,ou=people,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal
[11/Nov/2014:16:33:55 -0700] - candidate list has 1 ids
[11/Nov/2014:16:33:55 -0700] id2entry - => id2entry(19)
[11/Nov/2014:16:33:55 -0700] id2entry - <= id2entry 7f7d300101a0, dn
"uid=USER,ou=people,dc=DOMAIN,dc=com" (cache)
[11/Nov/2014:16:33:55 -0700] id2entry - <= id2entry( 19 ) 7f7d300101a0 (disk)
[11/Nov/2014:16:33:55 -0700] - => send_ldap_search_entry
(uid=USER,ou=People,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Account Usability Plugin' #1
type 410
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'deref' #4 type 410
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 410
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_search_entry
[11/Nov/2014:16:33:55 -0700] - => send_ldap_result 0::
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_result
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_vattr_get
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_getref
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_getref
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_query_attr
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_find_attr
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_find_attr
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_query_attr
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_release
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_release
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_vattr_get
[11/Nov/2014:16:33:55 -0700] - => find_entry_internal
(dn=uid=USER,ou=People,dc=DOMAIN,dc=com) lock 0
[11/Nov/2014:16:33:55 -0700] - => dn2entry_ext
"uid=USER,ou=People,dc=DOMAIN,dc=com"
[11/Nov/2014:16:33:55 -0700] - <= dn2entry_ext 7f7d300101a0
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal_dn found
(uid=USER,ou=People,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal
[11/Nov/2014:16:33:55 -0700] - => slapi_pw_find value: "PASSWORD"
[11/Nov/2014:16:33:55 -0700] - <= slapi_pw_find matched "PASSWORD_HASH"
using
scheme "SSHA"
[11/Nov/2014:16:33:55 -0700] - => reslimit_update_from_entry()
conn=0x9465f290, entry=0x48011630
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 0 (based on nsLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 1 (based on nsIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 2 (based on nsPagedLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 3 (based on nsPagedIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 4 (based on nsRangeSearchLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 5 (based on nsSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 6 (based on nsTimeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 7 (based on nsPagedSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 8 (based on nsIdleTimeout)
[11/Nov/2014:16:33:55 -0700] - <= reslimit_update_from_entry() returning status 0
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit()
conn=0x9465f290, handle=8
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - =>
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - <=
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - =>
slapi_add_pwd_control
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
postoperation plugin' #5 type 501
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:56 -0700] - conn 2836 leaving turbo mode due to 4
[11/Nov/2014:16:33:56 -0700] - listener got signaled
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[simple_bind_send] (0x0100): Executing simple bind as:
uid=USER,ou=People,dc=DOMAIN,dc=com
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[sdap_process_result] (0x2000): Trace: sh[0x7f9292dfc200], connected[1],
ops[0x7f9292dff790], ldap[0x7f9292dfad00]
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_dispatch] (0x4000): dbus conn: 0x7f9292cf6f80
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_dispatch] (0x4000): Dispatching.
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_message_handler] (0x4000): Received SBUS method [ping]
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_handler_got_caller_id] (0x4000): Received SBUS method [ping]
and sssd keeps making new connections:
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_port_status] (0x1000):
Port status of port 389 for server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x1000): Saving the first resolved server
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x0200): Found address for server ldap.cora.DOMAIN.com: [10.10.10.1] TTL 21600
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_uri_callback] (0x0400):
Constructed uri 'ldap://ldap.cora.DOMAIN.com/'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x4000):
Using file descriptor [22] for LDAP connection.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x0400):
Setting 6 seconds timeout for connecting
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to
[ldap://ldap.cora.DOMAIN.com:389/??base] with fd [22].
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_sys_connect_done]
(0x0100): Executing START TLS
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292d286d0], connected[1], ops[0x7f9292dfb250], ldap[0x7f9292de3290]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_EXTENDED]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_connect_done] (0x0080):
START TLS result: Success(0), Start TLS request accepted.Server willing to
negotiate SSL.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 389 of server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_set_port_status] (0x0400):
Marking port 389 of duplicate server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_callback": 0x7f9292e3e8a0
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_timeout": 0x7f9292e3e9d0
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Running timer
event 0x7f9292e3e8a0 "ltdb_callback"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Destroying
timer event 0x7f9292e3e9d0 "ltdb_timeout"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Ending timer
event 0x7f9292e3e8a0 "ltdb_callback"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=USER,ou=People,dc=DOMAIN,dc=com
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [simple_bind_send] (0x2000):
ldap simple bind sent, msgid = 2
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292d286d0], connected[1], ops[0x7f9292df92a0], ldap[0x7f9292de3290]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: ldap_result found nothing!
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_port_status] (0x1000):
Port status of port 389 for server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x1000): Saving the first resolved server
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x0200): Found address for server ldap.cora.DOMAIN.com: [10.10.10.1] TTL 21600
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_uri_callback] (0x0400):
Constructed uri 'ldap://ldap.cora.DOMAIN.com/'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x4000):
Using file descriptor [23] for LDAP connection.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x0400):
Setting 6 seconds timeout for connecting
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to
[ldap://ldap.cora.DOMAIN.com:389/??base] with fd [23].
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_sys_connect_done]
(0x0100): Executing START TLS
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292dfbed0], connected[1], ops[0x7f9292e38950], ldap[0x7f9292dff310]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_EXTENDED]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_connect_done] (0x0080):
START TLS result: Success(0), Start TLS request accepted.Server willing to
negotiate SSL.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 389 of server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_set_port_status] (0x0400):
Marking port 389 of duplicate server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_callback": 0x7f9292e6ae30
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_timeout": 0x7f9292e6aef0
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Running timer
event 0x7f9292e6ae30 "ltdb_callback"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Destroying
timer event 0x7f9292e6aef0 "ltdb_timeout"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Ending timer
event 0x7f9292e6ae30 "ltdb_callback"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=USER,ou=People,dc=DOMAIN,dc=com
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [simple_bind_send] (0x2000):
ldap simple bind sent, msgid = 2
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292dfbed0], connected[1], ops[0x7f9292d26dd0], ldap[0x7f9292dff310]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: ldap_result found nothing!
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus
conn: 0x7f9292cf6f80
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
Dispatching.
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_message_handler]
(0x4000): Received SBUS method [ping]
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_get_sender_id_send]
(0x2000): Not a sysbus message, quit
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_handler_got_caller_id]
(0x4000): Received SBUS method [ping]
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
12:02 p.m.
On 11/11/2014 05:01 PM, Orion Poplawski wrote:
On 11/05/2014 08:16 PM, Orion Poplawski wrote:
> Just recently we're seeing some very strange behavior on our system.
> Periodically we will see a sssd process start to have an ever greater number
> of connections to our ldap server until the server runs out of file
> descriptors. This seems to be happening with a particular user, who is having
> trouble logging in at times, particularly with email (dovecot). We see
> entries like the following on our sever:
>
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
> oid="1.3.6.1.4.1.1466.20037" name="startTLS"
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120 nentries=0
> etime=0
> [05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
> dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND msgid=2
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
>
> I don't yet have debug info from the sssd process. Any ideas from the above?
>
> Restarting the sssd process seems to clear things up for a while.
>
> - Orion
>
I tried turning on some error log tracing to see if that helps:
....
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal
[11/Nov/2014:16:33:55 -0700] - => slapi_pw_find value: "PASSWORD"
[11/Nov/2014:16:33:55 -0700] - <= slapi_pw_find matched "PASSWORD_HASH"
using
scheme "SSHA"
[11/Nov/2014:16:33:55 -0700] - => reslimit_update_from_entry()
conn=0x9465f290, entry=0x48011630
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 0 (based on nsLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 1 (based on nsIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 2 (based on nsPagedLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 3 (based on nsPagedIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 4 (based on nsRangeSearchLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 5 (based on nsSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 6 (based on nsTimeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 7 (based on nsPagedSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 8 (based on nsIdleTimeout)
[11/Nov/2014:16:33:55 -0700] - <= reslimit_update_from_entry() returning status 0
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit()
conn=0x9465f290, handle=8
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
So, on my good ldap server at this point I get:
[12/Nov/2014:10:54:20 -0700] - => send_ldap_result 0::
[12/Nov/2014:10:54:20 -0700] - <= send_ldap_result
but on my bad one instead I get:
[11/Nov/2014:16:33:55 -0700] - =>
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - <=
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - =>
slapi_add_pwd_control
which I don't see at all on the good one.
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster
replication
postoperation plugin' #5 type 501
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:56 -0700] - conn 2836 leaving turbo mode due to 4
[11/Nov/2014:16:33:56 -0700] - listener got signaled
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
1:26 p.m.
On 11/05/2014 08:16 PM, Orion Poplawski wrote:
Just recently we're seeing some very strange behavior on our
system.
Periodically we will see a sssd process start to have an ever greater number
of connections to our ldap server until the server runs out of file
descriptors. This seems to be happening with a particular user, who is having
trouble logging in at times, particularly with email (dovecot). We see
entries like the following on our sever:
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120 nentries=0
etime=0
[05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
[05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND msgid=2
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
[05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
I don't yet have debug info from the sssd process. Any ideas from the above?
This turns out to have been the bind hang bug introduced with the first fix
for https://fedorahosted.org/389/ticket/47748. It is present in
389-ds-base-1.2.11.32-1.el6 from the nhosoi/389-ds-base-epel6 COPR. It
appears to be fixed on the 389-ds-base-1.2.11 branch, so a new build with the
fix would be greatly appreciated. Thanks!
I may file a bug against sssd to handle hung connections better too.
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
1:38 p.m.
On 11/12/2014 12:26 PM, Orion Poplawski wrote:
On 11/05/2014 08:16 PM, Orion Poplawski wrote:
> Just recently we're seeing some very strange behavior on our system.
> Periodically we will see a sssd process start to have an ever greater number
> of connections to our ldap server until the server runs out of file
> descriptors. This seems to be happening with a particular user, who is having
> trouble logging in at times, particularly with email (dovecot). We see
> entries like the following on our sever:
>
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
> oid="1.3.6.1.4.1.1466.20037" name="startTLS"
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120 nentries=0
> etime=0
> [05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
> dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND msgid=2
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
>
> I don't yet have debug info from the sssd process. Any ideas from the above?
This turns out to have been the bind hang bug introduced with the first fix
for https://fedorahosted.org/389/ticket/47748. It is present in
389-ds-base-1.2.11.32-1.el6 from the nhosoi/389-ds-base-epel6 COPR. It
appears to be fixed on the 389-ds-base-1.2.11 branch, so a new build with the
fix would be greatly appreciated. Thanks!
New build where? From where are you getting your 389-ds-base package?
I may file a bug against sssd to handle hung connections better too.
3:20 p.m.
On 11/12/2014 12:38 PM, Rich Megginson wrote:
> This turns out to have been the bind hang bug introduced with the
first fix
> for https://fedorahosted.org/389/ticket/47748. It is present in
> 389-ds-base-1.2.11.32-1.el6 from the nhosoi/389-ds-base-epel6 COPR. It
> appears to be fixed on the 389-ds-base-1.2.11 branch, so a new build with the
> fix would be greatly appreciated. Thanks!
New build where? From where are you getting your 389-ds-base package?
The nhosoi/389-ds-base-epel6 COPR (as stated). However, I see that this is a
bad place to get it, so I've "downgraded" to 1.2.11.15-48 from EL6.6.
--
Orion Poplawski
Technical Manager 303-415-9701 x222
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane orion(a)nwra.com
Boulder, CO 80301 http://www.nwra.com
3:23 p.m.
On 11/12/2014 01:20 PM, Orion Poplawski wrote:
On 11/12/2014 12:38 PM, Rich Megginson wrote:
>> This turns out to have been the bind hang bug introduced with the first fix
>> for https://fedorahosted.org/389/ticket/47748. It is present in
>> 389-ds-base-1.2.11.32-1.el6 from the nhosoi/389-ds-base-epel6 COPR. It
>> appears to be fixed on the 389-ds-base-1.2.11 branch, so a new build with the
>> fix would be greatly appreciated. Thanks!
> New build where? From where are you getting your 389-ds-base package?
>
The nhosoi/389-ds-base-epel6 COPR (as stated). However, I see that this is a
bad place to get it, so I've "downgraded" to 1.2.11.15-48 from EL6.6.
Thank you, Orion.
As announced, it'd be a good timing to eliminate the copr test builds:
http://www.port389.org/docs/389ds/releases/end-1-2-11.html
Best regards,
--noriko
3453
days inactive
3459
days old
389-users@lists.fedoraproject.org
18 comments
4 participants
participants (4)
-
Noriko Hosoi -
Orion Poplawski -
Paul Robert Marino -
Rich Megginson