[389-users] Skipped request ...

Thu May 13 20:46:15 UTC 2010

Hi Rick,

I attached access and error file with debug level 8. The server does not respond to any requests anymore. If you kill the client, it responds afterwards.

Let me know, what you see.

Thanks,
-Reinhard 

-----Original Message-----
From: 389-users-bounces at lists.fedoraproject.org [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of Rich Megginson
Sent: Thursday, May 13, 2010 1:10 PM
To: General discussion list for the 389 Directory server project.
Subject: Re: [389-users] Skipped request ...

Reinhard Nappert wrote:
> Rich, which debugging level do you suggest? Apparently, I tried to much, because it would crash the server constantly.
Debugging levels should not crash the server - can provide more information about the crash?
> For now, I go just with 8 (Connection Management). Seeing the problem, what would you enable?
>   
Yes, start with 8.
> Thanks,
> -Reinhard
>
> -----Original Message-----
> From: 389-users-bounces at lists.fedoraproject.org 
> [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of Rich 
> Megginson
> Sent: Wednesday, May 12, 2010 6:50 PM
> To: General discussion list for the 389 Directory server project.
> Subject: Re: [389-users] Skipped request ...
>
> Reinhard Nappert wrote:
>   
>> Hi Rich,
>>
>> I ran some further tests. This entire thing looks kind of weird. I have a kind of monitoring tool, I use to figure out if the server still responds in a timely manner. This tool performs an anonymous bind and reads a specific object, every 30 seconds.
>>     
> Does it perform an unbind operation?  Does it disconnect the socket?
>   
>>  What I see is that the server responds to the incoming request and it performs about 500 requests within those 30 seconds. Then, I see, when the next monitoring connection request comes is, but I never see the bind. Since this times out, the monitoring tool restarts the server after a while (about 10 seconds).
>>
>> Here are the logs in access:
>> [11/May/2010:22:12:20 -0400] conn=94 fd=83 slot=83 connection from
>> 127.0.0.1 to 127.0.0.1
>> [11/May/2010:22:13:24 -0400] conn=0 fd=64 slot=64 SSL connection from
>> 10.227.6.45 to 10.227.6.53
>>
>> So, you see the server does not respond to any requests after 
>> [11/May/2010:22:12:20 -0400] conn=94 fd=83 slot=83 connection from
>> 127.0.0.1 to 127.0.0.1
>>
>> And start responding, once it was restarted:
>> [11/May/2010:22:13:24 -0400] conn=0 fd=64 slot=64 SSL connection from
>> 10.227.6.45 to 10.227.6.53
>>
>> I was wondering , if we could get somehow some debugging out of ns-slapd, once it is in this state (truss or something else).
>>   
>>     
> http://directory.fedoraproject.org/wiki/FAQ#Troubleshooting
> If that produces too much error log output, or kills the performance, 
> you can also try replacing the error log with a named pipe+script - 
> http://directory.fedoraproject.org/wiki/Named_Pipe_Log_Script
> man ds-logpipe.py
>   
>> Any help is appreciated.
>>
>> Thanks,
>> -Reinhard
>>
>>
>> -----Original Message-----
>> From: 389-users-bounces at lists.fedoraproject.org 
>> [mailto:389-users-bounces at lists.fedoraproject.org] On Behalf Of Rich 
>> Megginson
>> Sent: Tuesday, May 11, 2010 5:21 PM
>> To: General discussion list for the 389 Directory server project.
>> Subject: Re: [389-users] Skipped request ...
>>
>> Reinhard Nappert wrote:
>>   
>>     
>>> Hi all,
>>>  
>>> I have seen a weird behavior of my DS (1.1.2). It has a very small 
>>> database (only about 2300 objects). A client performed a one-level 
>>> search retrieving the children. The server find 114 objects, but the 
>>> search was very slow:
>>>  
>>> [06/May/2010:12:23:11 +0000] conn=127 op=149 SRCH base=<base> 
>>> scope=1 filter="(&(&(objectClass=<xyz>)(<att1>=value))(!(<att2>=TRUE)))"
>>>  
>>> yes, the filter is a bit complex, but both attribute types <att1> 
>>> and <att2> are indexed. This search usually is fast. It looks to me 
>>> that the server is already in a funny state.
>>> ...
>>> [06/May/2010:12:23:17 +0000] conn=127 op=149 RESULT err=3 tag=101
>>> nentries=114 etime=7
>>>     
>>>       
>> err=3 is TIMELIMIT_EXCEEDED - that's probably why you aren't getting all of the results you expect, and could be why it's skipping the op.
>>   
>>     
>>>  
>>> When the client gets the results, it iterates over those and gets 
>>> its children, like:
>>>  
>>> [06/May/2010:12:23:17 +0000] conn=127 op=150 SRCH base=<dn of result 
>>> from previous SRCH> scope=1 
>>> filter="(&(&(objectClass=<uvw>)(<attr3>=*))(!(<attr2>=TRUE)))" attrs=ALL.
>>> Those searches are quick:
>>> [06/May/2010:12:23:17 +0000] conn=127 op=150 RESULT err=0 tag=101
>>> nentries=1 etime=0
>>>  
>>> but somehow the server does not process on of the requests, when the 
>>> client iterates over the results:
>>>  
>>> [06/May/2010:12:23:18 +0000] conn=127 op=263 SRCH base=<dn of result 
>>> from previous SRCH> scope=1 
>>> filter="(&(&(objectClass=<uvw>)(<attr3>=*))(!(<attr2>=TRUE)))" attrs=ALL.
>>> [06/May/2010:12:23:18 +0000] conn=127 op=263 RESULT err=0 tag=101
>>> nentries=1 etime=0
>>> [06/May/2010:12:23:26 +0000] conn=127 op=265 SRCH base=<dn of result 
>>> from previous SRCH> scope=1 
>>> filter="(&(&(objectClass=<uvw>)(<attr3>=*))(!(<attr2>=TRUE)))" attrs=ALL.
>>> [06/May/2010:12:23:26 +0000] conn=127 op=265 RESULT err=0 tag=101 
>>> nentries=0 etime=0 You can see that the server skipped op=264. It 
>>> looks to me that the request came in, but somehow the server joked 
>>> up, before it could log the request in access.
>>>  
>>> Has anybody seen such a behavior before?
>>>  
>>> Thanks,
>>> -Reinhard
>>>
>>>  
>>> --------------------------------------------------------------------
>>> --
>>> --
>>>
>>> --
>>> 389 users mailing list
>>> 389-users at lists.fedoraproject.org
>>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>>>     
>>>       
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>>   
>>     
>
> --
> 389 users mailing list
> 389-users at lists.fedoraproject.org
> https://admin.fedoraproject.org/mailman/listinfo/389-users
> --
> 389 users mailing list
> 389-users at lists.fedoraproject.org
> https://admin.fedoraproject.org/mailman/listinfo/389-users
>   

--
389 users mailing list
389-users at lists.fedoraproject.org
https://admin.fedoraproject.org/mailman/listinfo/389-users
-------------- next part --------------
A non-text attachment was scrubbed...
Name: errors
Type: application/octet-stream
Size: 59858 bytes
Desc: errors
URL: <http://lists.fedoraproject.org/pipermail/389-users/attachments/20100513/9586f2ef/attachment.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: access
Type: application/octet-stream
Size: 54959 bytes
Desc: access
URL: <http://lists.fedoraproject.org/pipermail/389-users/attachments/20100513/9586f2ef/attachment-0001.obj>