*** DRAFT *** DRAFT *** DRAFT *** DRAFT *** DRAFT *** DRAFT ***

Statslog() patch to CVS HEAD, 2005-07-25, for ITS#3281.

- Patch #1.

  Add missing Statslog() statements (loglevel stats/stats2):
  "ABANDON", "STARTTLS", "CANCEL", "WHOAMI", "PASSMOD".
  "TLS established" (in addition to STARTTLS and its RESULT,
  and with only "conn=" in front, not "op=").
  "EXT oid=..." for unsupported extended operations.
  "RESULT" for SASL bind, "RESULT oid=..." for extended response.
  "INTERM oid=..." for intermediate responses (loglevel stats2).

  That misses some significant connection events, so:

- Patch #2.

  In Statslog output "conn=xx fd=yy closed", append the reason in
  "()" unless client or server closed the connection after Unbind.
  Currently known reasons are "connection lost", "slapd shutdown",
  "idletimeout", "operations error", "TLS negotiation failure",
  "SASL layer install failure", "connection lost on write".

Still missing Statslog output from a number of failed requests,
e.g. unrecognized critical controls and bad base DNs.  That would
take more thorough Statslog revamping, so I'll get back to it
later.

========================================================================

Index: servers/slapd/abandon.c
--- servers/slapd/abandon.c	14 Jul 2005 17:52:08 -0000	1.50
+++ servers/slapd/abandon.c	23 Jul 2005 17:38:50 -0000
@@ -52,4 +52,7 @@
 	}
 
+	Statslog( LDAP_DEBUG_STATS, "%s ABANDON msg=%ld\n",
+		op->o_log_prefix, (long) id, 0, 0, 0 );
+
 	if( get_ctrls( op, rs, 0 ) != LDAP_SUCCESS ) {
 		Debug( LDAP_DEBUG_ANY, "do_abandon: get_ctrls failed\n", 0, 0 ,0 );
Index: servers/slapd/cancel.c
--- servers/slapd/cancel.c	11 Jul 2005 10:11:15 -0000	1.20
+++ servers/slapd/cancel.c	23 Jul 2005 17:38:50 -0000
@@ -61,4 +61,7 @@
 	}
 
+	Statslog( LDAP_DEBUG_STATS, "%s CANCEL msg=%d\n",
+		op->o_log_prefix, opid, 0, 0, 0 );
+
 	ldap_pvt_thread_mutex_lock( &op->o_conn->c_mutex );
 	LDAP_STAILQ_FOREACH( o, &op->o_conn->c_pending_ops, o_next ) {
Index: servers/slapd/connection.c
--- servers/slapd/connection.c	21 Jul 2005 17:14:09 -0000	1.313
+++ servers/slapd/connection.c	23 Jul 2005 17:38:50 -0000
@@ -1248,4 +1249,7 @@
 					s, rc, c->c_connid );
 			}
+			Statslog( LDAP_DEBUG_STATS,
+				"conn=%lu TLS established tls_ssf=%u ssf=%u\n",
+			    c->c_connid, c->c_tls_ssf, c->c_ssf, 0, 0 );
 			slap_sasl_external( c, c->c_tls_ssf, &authid );
 			if ( authid.bv_val ) free( authid.bv_val );
Index: servers/slapd/extended.c
--- servers/slapd/extended.c	22 Jul 2005 03:49:55 -0000	1.82
+++ servers/slapd/extended.c	23 Jul 2005 17:38:50 -0000
@@ -167,4 +167,6 @@
 	/* check for controls inappropriate for all extended operations */
 	if( get_manageDSAit( op ) == SLAP_CONTROL_CRITICAL ) {
+		Statslog( LDAP_DEBUG_STATS, "%s EXT oid=%s\n",
+		    op->o_log_prefix, op->ore_reqoid.bv_val, 0, 0, 0 );
 		send_ldap_error( op, rs,
 			LDAP_UNAVAILABLE_CRITICAL_EXTENSION,
@@ -197,4 +199,6 @@
 	if( !(ext = find_extop(supp_ext_list, &op->ore_reqoid )))
 	{
+		Statslog( LDAP_DEBUG_STATS, "%s EXT oid=%s\n",
+		    op->o_log_prefix, op->ore_reqoid.bv_val, 0, 0, 0 );
 		Debug( LDAP_DEBUG_ANY, "do_extended: unsupported operation \"%s\"\n",
 			op->ore_reqoid.bv_val, 0 ,0 );
@@ -329,4 +333,7 @@
 	}
 
+	Statslog( LDAP_DEBUG_STATS, "%s WHOAMI\n",
+	    op->o_log_prefix, 0, 0, 0, 0 );
+
 	op->o_bd = op->o_conn->c_authz_backend;
 	if( backend_check_restrictions( op, rs,
Index: servers/slapd/passwd.c
--- servers/slapd/passwd.c	18 Jul 2005 04:22:34 -0000	1.109
+++ servers/slapd/passwd.c	23 Jul 2005 17:38:50 -0000
@@ -62,21 +62,34 @@
 	assert( ber_bvcmp( &slap_EXOP_MODIFY_PASSWD, &op->ore_reqoid ) == 0 );
 
-	if( op->o_dn.bv_len == 0 ) {
-		rs->sr_text = "only authenticated users may change passwords";
-		return LDAP_STRONG_AUTH_REQUIRED;
-	}
-
 	qpw->rs_old.bv_val = NULL;
 	qpw->rs_new.bv_val = NULL;
 	qpw->rs_mods = NULL;
 	qpw->rs_modtail = NULL;
+	rs->sr_text = NULL;
 
 	rs->sr_err = slap_passwd_parse( op->ore_reqdata, &id, &qpw->rs_old,
 		&qpw->rs_new, &rs->sr_text );
 
+	if ( rs->sr_err == LDAP_SUCCESS && !BER_BVISEMPTY( &id ) ) {
+		Statslog( LDAP_DEBUG_STATS, "%s PASSMOD id=\"%s\"%s%s\n",
+			op->o_log_prefix, id.bv_val,
+			qpw->rs_old.bv_val ? " old" : "",
+			qpw->rs_new.bv_val ? " new" : "", 0 );
+	} else {
+		Statslog( LDAP_DEBUG_STATS, "%s PASSMOD\n",
+			op->o_log_prefix,
+			qpw->rs_old.bv_val ? " old" : "",
+			qpw->rs_new.bv_val ? " new" : "", 0, 0 );
+	}
+
 	if ( rs->sr_err != LDAP_SUCCESS ) {
 		return rs->sr_err;
 	}
 
+	if( op->o_dn.bv_len == 0 ) {
+		rs->sr_text = "only authenticated users may change passwords";
+		return LDAP_STRONG_AUTH_REQUIRED;
+	}
+
 	if ( !BER_BVISEMPTY( &id ) ) {
 		rs->sr_err = dnPrettyNormal( NULL, &id, &op->o_req_dn,
Index: servers/slapd/result.c
--- servers/slapd/result.c	23 Jul 2005 09:55:09 -0000	1.265
+++ servers/slapd/result.c	23 Jul 2005 17:38:50 -0000
@@ -614,5 +614,10 @@
 	rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0;
 
-	send_ldap_response( op, rs );
+	if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) {
+		Statslog( LDAP_DEBUG_STATS,
+			"%s RESULT tag=%lu err=%d text=%s\n",
+			op->o_log_prefix, rs->sr_tag, rs->sr_err,
+			rs->sr_text ? rs->sr_text : "", 0 );
+	}
 }
 
@@ -631,5 +636,10 @@
 	rs->sr_msgid = (rs->sr_tag != LBER_SEQUENCE) ? op->o_msgid : 0;
 
-	send_ldap_response( op, rs );
+	if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) {
+		Statslog( LDAP_DEBUG_STATS,
+			"%s RESULT oid=%s err=%d text=%s\n",
+			op->o_log_prefix, rs->sr_rspoid ? rs->sr_rspoid : "",
+			rs->sr_err, rs->sr_text ? rs->sr_text : "", 0 );
+	}
 }
 
@@ -645,5 +655,10 @@
 	rs->sr_tag = LDAP_RES_INTERMEDIATE;
 	rs->sr_msgid = op->o_msgid;
-	send_ldap_response( op, rs );
+	if ( send_ldap_response( op, rs ) == SLAP_CB_CONTINUE ) {
+		Statslog( LDAP_DEBUG_STATS2,
+			"%s INTERM oid=%s\n",
+			op->o_log_prefix,
+			rs->sr_rspoid ? rs->sr_rspoid : "", 0, 0, 0 );
+	}
 }
 
Index: servers/slapd/starttls.c
--- servers/slapd/starttls.c	11 Jul 2005 10:11:15 -0000	1.38
+++ servers/slapd/starttls.c	23 Jul 2005 17:38:51 -0000
@@ -28,4 +28,7 @@
 	int rc;
 
+	Statslog( LDAP_DEBUG_STATS, "%s STARTTLS\n",
+	    op->o_log_prefix, 0, 0, 0, 0 );
+
 	if ( op->ore_reqdata != NULL ) {
 		/* no request data should be provided */
Index: servers/slapd/back-ldap/config.c
--- servers/slapd/back-ldap/config.c	22 Jul 2005 11:21:10 -0000	1.91
+++ servers/slapd/back-ldap/config.c	23 Jul 2005 17:38:52 -0000
@@ -1546,4 +1546,7 @@
 	}
 
+	Statslog( LDAP_DEBUG_STATS, "%s WHOAMI\n",
+	    op->o_log_prefix, 0, 0, 0, 0 );
+
 	rs->sr_err = backend_check_restrictions( op, rs, 
 			(struct berval *)&slap_EXOP_WHOAMI );

========================================================================

In Statslog output "closed", add the closure reason in parens
unless client or server closed the connection after Unbind.

Index: servers/slapd/slap.h
--- servers/slapd/slap.h	22 Jul 2005 05:54:17 -0000	1.704
+++ servers/slapd/slap.h	23 Jul 2005 17:38:51 -0000
@@ -2531,4 +2531,5 @@
 	int			c_conn_state;	/* connection state */
 	int			c_conn_idx;		/* slot in connections array */
+	const char	*c_close_reason; /* why connection is closing */
 
 	ldap_pvt_thread_mutex_t	c_mutex; /* protect the connection */
Index: servers/slapd/proto-slap.h
--- servers/slapd/proto-slap.h	23 Jul 2005 09:32:10 -0000	1.610
+++ servers/slapd/proto-slap.h	23 Jul 2005 17:38:50 -0000
@@ -577,5 +577,6 @@
 	struct berval *id ));
 
-LDAP_SLAPD_F (void) connection_closing LDAP_P(( Connection *c ));
+LDAP_SLAPD_F (void) connection_closing LDAP_P((
+	Connection *c, const char *why ));
 LDAP_SLAPD_F (int) connection_state_closing LDAP_P(( Connection *c ));
 LDAP_SLAPD_F (const char *) connection_state2str LDAP_P(( int state ))
Index: servers/slapd/connection.c
--- servers/slapd/connection.c	21 Jul 2005 17:14:09 -0000	1.313
+++ servers/slapd/connection.c	23 Jul 2005 17:38:50 -0000
@@ -51,4 +51,6 @@
 static unsigned long conn_nextid = 0;
 
+static const char conn_lost_str[] = "connection lost";
+
 /* structure state (protected by connections_mutex) */
 #define SLAP_C_UNINITIALIZED	0x00	/* MUST BE ZERO (0) */
@@ -192,5 +194,5 @@
 
 		/* connections_mutex and c_mutex are locked */
-		connection_closing( &connections[i] );
+		connection_closing( &connections[i], "slapd shutdown" );
 		connection_close( &connections[i] );
 
@@ -223,5 +225,5 @@
 		if( difftime( c->c_activitytime+global_idletimeout, now) < 0 ) {
 			/* close it */
-			connection_closing( c );
+			connection_closing( c, "idletimeout" );
 			connection_close( c );
 			i++;
@@ -493,4 +495,5 @@
 		c->c_conn_state = SLAP_C_CLIENT;
 		c->c_struct_state = SLAP_C_USED;
+		c->c_close_reason = "?";			/* should never be needed */
 		ber_sockbuf_ctrl( c->c_sb, LBER_SB_OPT_SET_FD, &s );
 		ldap_pvt_thread_mutex_unlock( &c->c_mutex );
@@ -564,4 +567,5 @@
 	c->c_conn_state = SLAP_C_INACTIVE;
 	c->c_struct_state = SLAP_C_USED;
+	c->c_close_reason = "?";			/* should never be needed */
 
 	c->c_ssf = c->c_transport_ssf = ssf;
@@ -626,4 +630,5 @@
 	ber_socket_t	sd;
 	unsigned long	connid;
+	const char		*close_reason;
 
 	assert( connections != NULL );
@@ -636,4 +641,5 @@
 	/* only for stats (print -1 as "%lu" may give unexpected results ;) */
 	connid = c->c_connid;
+	close_reason = c->c_close_reason;
 
 	backend_connection_destroy(c);
@@ -673,7 +679,8 @@
 		slapd_remove( sd, 1, 0 );
 
-		Statslog( LDAP_DEBUG_STATS,
-			"conn=%lu fd=%ld closed\n",
-			connid, (long) sd, 0, 0, 0 );
+		Statslog( LDAP_DEBUG_STATS, (close_reason
+									 ? "conn=%lu fd=%ld closed (%s)\n"
+									 : "conn=%lu fd=%ld closed\n"),
+			connid, (long) sd, close_reason, 0, 0 );
 	}
 
@@ -689,4 +696,5 @@
 	c->c_conn_state = SLAP_C_INVALID;
 	c->c_struct_state = SLAP_C_UNUSED;
+	c->c_close_reason = "?";			/* should never be needed */
 
 #ifdef LDAP_SLAPI
@@ -741,5 +749,5 @@
 }
 
-void connection_closing( Connection *c )
+void connection_closing( Connection *c, const char *why )
 {
 	assert( connections != NULL );
@@ -759,4 +767,5 @@
 		/* update state to closing */
 		c->c_conn_state = SLAP_C_CLOSING;
+		c->c_close_reason = why;
 
 		/* don't listen on this port anymore */
@@ -774,4 +783,7 @@
 			ldap_pvt_thread_mutex_lock( &c->c_mutex );
 		}
+	} else if( why == NULL && c->c_close_reason == conn_lost_str ) {
+		/* Client closed connection after doing Unbind. */
+		c->c_close_reason = NULL;
 	}
 }
@@ -1086,5 +1098,6 @@
 	case LDAP_REQ_UNBIND:
 		/* c_mutex is locked */
-		connection_closing( conn );
+		connection_closing(
+			conn, tag == LDAP_REQ_UNBIND ? NULL : "operations error" );
 		break;
 
@@ -1145,4 +1158,5 @@
 	c->c_conn_state = SLAP_C_INVALID;
 	c->c_struct_state = SLAP_C_UNUSED;
+	c->c_close_reason = "?";			/* should never be needed */
 	connection_return( c );
 	slapd_remove( s, 0, 1 );
@@ -1210,5 +1224,5 @@
 			c->c_needs_tls_accept = 0;
 			/* connections_mutex and c_mutex are locked */
-			connection_closing( c );
+			connection_closing( c, "TLS negotiation failure" );
 
 #if 0
@@ -1282,5 +1299,5 @@
 				s, rc, c->c_connid );
 			/* connections_mutex and c_mutex are locked */
-			connection_closing( c );
+			connection_closing( c, "SASL layer install failure" );
 			connection_close( c );
 			connection_return( c );
@@ -1311,5 +1328,5 @@
 			s, rc, c->c_connid );
 		/* connections_mutex and c_mutex are locked */
-		connection_closing( c );
+		connection_closing( c, conn_lost_str );
 		connection_close( c );
 		connection_return( c );
Index: servers/slapd/result.c
--- servers/slapd/result.c	23 Jul 2005 09:55:09 -0000	1.265
+++ servers/slapd/result.c	23 Jul 2005 17:38:50 -0000
@@ -190,5 +190,5 @@
 
 		if ( err != EWOULDBLOCK && err != EAGAIN ) {
-			connection_closing( conn );
+			connection_closing( conn, "connection lost on write" );
 
 			ldap_pvt_thread_mutex_unlock( &conn->c_mutex );