Ben Beuchler wrote: Where does it say there's an error here? It means that an operation that was just received on that connection has been deferred, because there are other operations ahead of it that are still pending. I.e., there's a bunch of operations on that connection waiting to execute, and the newcomer is last in line. -- -- Howard Chu Chief Architect, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/

Ben Beuchler wrote: The only time I've seen this occur on a frequent basis is with poorly written clients like Sendmail, which sends off a stream of a hundred or so search requests on a connection before it checks for any replies. The problem there is that the search replies build up in the network and socket buffers and once the socket buffer gets full we can't send anything else. At that point we stop executing operations on the connection; we just wait for the client to drain it. -- -- Howard Chu Chief Architect, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/

Ben Beuchler writes: Include 256 in your loglevel, if you haven't already, and look for the '<date> swizzle slapd[<pid>]: conn=<num> ...' lines it produces. In particular, look for 'conn=<num> op=<num> RESULT' lines _after_ the 'deferring operation' line, where the matched received operation (same conn and op) was _before_ that line. Notice what the operation was, and what the result code was (RESULT ... err=). You'll find the result code descriptions in RFC 4511. Note that logging is a bit sloppy - for requests with syntax errors or some other problems, only the response is logged. But since these requests fail without processing they shouldn't take time either. -- Regards, Hallvard

My apologies; I neglected to include an example of the "deferring operation: binding" log entries: Apr 11 15:14:49 cliff slapd[15355]: conn=1 op=36640 BIND anonymous mech=implicit ssf=0 Apr 11 15:14:49 cliff slapd[15355]: conn=1 op=36640 BIND dn="uid=bbrogan,dc=users,dc=accounts,dc=ldap,dc=mcad,dc=edu" method=128 Apr 11 15:14:49 cliff slapd[15355]: conn=1 op=36640 BIND dn="uid=bbrogan,dc=users,dc=accounts,dc=ldap,dc=mcad,dc=edu" mech=SIMPLE ssf=0 Apr 11 15:14:49 cliff slapd[15355]: conn=1 op=36640 RESULT tag=97 err=0 text= Apr 11 15:14:50 cliff slapd[15355]: connection_input: conn=1 deferring operation: binding Apr 11 15:14:50 cliff slapd[15355]: conn=1 op=36641 BIND anonymous mech=implicit ssf=0 Apr 11 15:14:50 cliff slapd[15355]: conn=1 op=36641 BIND dn="" method=128 Apr 11 15:14:50 cliff slapd[15355]: conn=1 op=36641 RESULT tag=97 err=0 text= It appears to my untrained eye that the operation both before and after the deferral completed successfully. Any idea what type of client behavior could trigger messages like this? -Ben

2.3.32 It's entirely possible that I'm chasing a red herring. My primary goal in posting here was to find out what, exactly, the deferral messages indicated and, from that, whether or not they could be responsible for the problems I'm seeing. Thanks to the very clear, helpful responses from you, Pierangelo, Hallvard, and others I'm fairly confident I'll be able to rule the deferrals either in or out as relevant to my problem with a few more troubleshooting steps. Thanks! -Ben

There is an actual problem (intermittent hanging of the authentication process under load) but I have nothing more than anecdote to tie it to the deferrals. At this point they are the only lead I have. I'm hoping that whatever the client's doing to cause the deferrals is, eventually, producing the auth failures. -Ben

Ben Beuchler writes: 97 is BindResponse. But it's easier to take the conn=1 op=36051 in the RESULT, and find the matching conn=1 op=36051 request. Each request on a connection gets its own op number. Don't be confused by the several BINDs with the same conn+op - that means several things are happening with that request or slapd wanted to log more than one line's worth of data. In this case, the mech=implicit Bind is because any Bind first reverts the connection to anonymous if it is not already anonymous. BTW, I notice the requests/responses you've posted were less than 2 or often 1 seconds apart - is that how long clients hang, or are there some really long hangs? On another note, maybe you can dispatch the Binds to e.g. 4 processes and thus 4 connections, thus reducing much of the sequencing. -- Regards, Hallvard

Ben Beuchler wrote: I'd note that if your client is performing search + bind on the same connection in an asynchronous manner, then the server behavior as per RFC4511 is undefined, since a server is not supposed to be willing to handle operations intermixed with binds until a bind is concluded. That is, any operation can be multiplexed on a single LDAP connection __except__ binds, which must be serialized. A more appropriate client for that type of operations would need to use at least 2 connections, one for searches and one for binds, and the one for binds should take care of either performing synchronous binds, or in any case to wait for response to a bind before performing another. In case of failure (e.g. timeout) while waiting for bind response, the connection should be trashed (see ldap_unbind_ext(3)) and recreated. This is what is done, for example, by slapd-ldap(5). p. Ing. Pierangelo Masarati OpenLDAP Core Team SysNet s.r.l. via Dossi, 8 - 27100 Pavia - ITALIA http://www.sys-net.it --------------------------------------- Office: +39 02 23998309 Mobile: +39 333 4963172 Email: pierangelo.masarati(a)sys-net.it ---------------------------------------