[Date Prev][Date Next] [Chronological] [Thread] [Top]

OpenLDAP 2.1.22 and "deferring operation" error message



Hi!

We've got OpenLDAP 2.1.22 server running in our company. It's being used as a corporate address book and authentication database, and is used by our mail server as database of accounts.

Occasionally we get reports from users not being able to query LDAP, or send mail. Investigation always reveals that the following messages accompany the problem in slapd logs (/var/log/daemon.log):

slapd[28256]: deferring operation

After numerous tries of remedying the problem by raising number of threads, limit of pending operations (with conn_max_pending, conn_pending_max, conn_max_pending_auth etc.), supplying reverse DNS records for all connecting IPs, changing database backend from LDBM to BDB, adding indices etc, etc, I've taken a look on openldap code to see where this error message is and found out that it's in connection.c, near line 1500:

 /* Don't process requests when the conn is in the middle of a
  * Bind, or if it's closing. Also, don't let any single conn
  * use up all the available threads, and don't execute if we're
  * currently blocked on output. And don't execute if there are
  * already pending ops, let them go first.
  */
 if ( conn->c_conn_state == SLAP_C_BINDING
   || conn->c_conn_state == SLAP_C_CLOSING
   || conn->c_n_ops_executing >= connection_pool_max/2
   || conn->c_n_ops_pending
   || conn->c_writewaiter)
 {
   int max = conn->c_dn.bv_len ? slap_conn_max_pending_auth
      : slap_conn_max_pending;
#ifdef NEW_LOGGING
   LDAP_LOG( CONNECTION, INFO,
     "connection_input: conn %lu  deferring operation\n",
     conn->c_connid, 0, 0 );
#else
   Debug( LDAP_DEBUG_ANY, "deferring operation\n", 0, 0, 0 );
#endif
   conn->c_n_ops_pending++;



This shows that the message can be caused by multiple conditions.

So I've prepared a patch to indicate which cause was in question. I'm attaching the patch for openldap source, as well as patch for Fedora SRPMS's spec file for easier preparation of RPMS.

After installing the modified version of OpenLDAP on our server it became evident that the cause is always the same:

slapd[12273]: deferring operation because of conn->c_conn_state == SLAP_C_BINDING

So it seems that the operations are deferred because the connection is in the process of binding. Any ideas how can this be remedied? Could anyone with inner knowledge comment on the way OpenLDAP works with respect to this?






diff -urN openldap-2.1.22/servers/slapd/connection.c openldap-2.1.22.alt/servers/slapd/connection.c
--- openldap-2.1.22/servers/slapd/connection.c	2003-05-18 21:58:56.000000000 +0200
+++ openldap-2.1.22.alt/servers/slapd/connection.c	2004-01-17 12:19:06.000000000 +0100
@@ -1484,12 +1484,28 @@
 	{
 		int max = conn->c_dn.bv_len ? slap_conn_max_pending_auth
 			 : slap_conn_max_pending;
+		char* cause;
+		char* errmsg;
+
+		if ( conn->c_conn_state == SLAP_C_BINDING )
+		  cause = "conn->c_conn_state == SLAP_C_BINDING";
+		else if ( conn->c_conn_state == SLAP_C_CLOSING )
+		  cause = "conn->c_conn_state == SLAP_C_CLOSING";
+		else if ( conn->c_n_ops_executing >= connection_pool_max/2 )
+		  cause = "conn->c_n_ops_executing >= connection_pool_max/2";
+		else if ( conn->c_n_ops_pending )
+		  cause = "conn->c_n_ops_pending";
+		else if ( conn->c_writewaiter )
+		  cause = "conn->c_writewaiter";
+	  else
+		  cause = "unknown cause";
+
 #ifdef NEW_LOGGING
 		LDAP_LOG( CONNECTION, INFO, 
-			"connection_input: conn %lu  deferring operation\n",
-			conn->c_connid, 0, 0 );
+			"connection_input: conn %lu  deferring operation because of %s\n",
+			conn->c_connid, cause, 0 );
 #else
-		Debug( LDAP_DEBUG_ANY, "deferring operation\n", 0, 0, 0 );
+		Debug( LDAP_DEBUG_ANY, "deferring operation because of %s\n", cause, 0, 0 );
 #endif
 		conn->c_n_ops_pending++;
 		LDAP_STAILQ_INSERT_TAIL( &conn->c_pending_ops, op, o_next );

--- openldap-2.1.22-8.spec	2003-10-23 16:13:30.000000000 +0200
+++ openldap-2.1.22-11alt.spec	2004-01-19 12:01:43.000000000 +0100
@@ -7,7 +7,7 @@
 Summary: The configuration files, libraries, and documentation for OpenLDAP.
 Name: openldap
 Version: 2.1.22
-Release: 8
+Release: 11alt
 License: OpenLDAP
 Group: System Environment/Daemons
 Source0: ftp://ftp.OpenLDAP.org/pub/OpenLDAP/openldap-release/openldap-%{version}.tgz
@@ -37,6 +37,7 @@
 Patch23: MigrationTools-27-simple.patch
 Patch24: MigrationTools-26-suffix.patch
 Patch25: MigrationTools-44-schema.patch
+Patch26: operation_deferred_detail_logging.patch
 URL: http://www.openldap.org/
 BuildRoot: %{_tmppath}/%{name}-%{version}-root
 BuildPreReq: cyrus-sasl-devel >= 2.1, gdbm-devel, libtool >= 1.5, krb5-devel
@@ -121,6 +122,8 @@
 %patch25 -p1 -b .schema
 popd
 
+%patch26 -p1
+
 pushd openldap-%{version_20}
 	for subdir in build-gdbm build-db ; do
 		mkdir $subdir