Add missing Statslog() statements (loglevel stats/stats2):

  "ABANDON", "STARTTLS", "CANCEL", "WHOAMI", "PASSMOD", "EXT", "INTERM",
  "TLS established", SASL and Extended Response "RESULT".
In Statslog output "conn=xx fd=yy closed", append the reason in
  "()" unless client or server closed the connection after Unbind.
Still missing Statslog output from a number of failed requests.

diff --git a/servers/slapd/abandon.c b/servers/slapd/abandon.c
index df2f937f497ad88b3dcadf832bfed1ac6ffc4f57..006a8c8f398eb178aa14f64c559ce7d415a9f1f1 100644 (file)
--- a/servers/slapd/abandon.c
+++ b/servers/slapd/abandon.c
@@ -51,6 +51,9 @@ do_abandon( Operation *op, SlapReply *rs )
                return SLAPD_DISCONNECT;
        }
 
+       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 );
                return rs->sr_err;

diff --git a/servers/slapd/back-ldap/config.c b/servers/slapd/back-ldap/config.c
index cf8aa6642fe133ab33fc1aaacf1f3b306e19febe..7968dc5331ece72a218cd054e96c080d6fb29e3c 100644 (file)
--- a/servers/slapd/back-ldap/config.c
+++ b/servers/slapd/back-ldap/config.c
@@ -1576,6 +1576,9 @@ ldap_back_exop_whoami(
                return rs->sr_err = LDAP_PROTOCOL_ERROR;
        }
 
+       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 );
        if( rs->sr_err != LDAP_SUCCESS ) return rs->sr_err;

diff --git a/servers/slapd/cancel.c b/servers/slapd/cancel.c
index c1b288c6d52bb5739995d0e6ed4c3f132bb68c73..16289a9d47f7595060d41d9882d0757dbec7637b 100644 (file)
--- a/servers/slapd/cancel.c
+++ b/servers/slapd/cancel.c
@@ -60,6 +60,9 @@ int cancel_extop( Operation *op, SlapReply *rs )
                return LDAP_PROTOCOL_ERROR;
        }
 
+       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 ) {
                if ( o->o_msgid == opid ) {

diff --git a/servers/slapd/connection.c b/servers/slapd/connection.c
index 56c02c2f7a199bf076fc1c228ccc7d21b221a763..217ba8da08812a91fb7035201cb69957c8e85522 100644 (file)
--- a/servers/slapd/connection.c
+++ b/servers/slapd/connection.c
@@ -50,6 +50,8 @@ static Connection *connections = NULL;
 static ldap_pvt_thread_mutex_t conn_nextid_mutex;
 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) */
 #define SLAP_C_UNUSED                  0x01
@@ -191,7 +193,7 @@ int connections_shutdown(void)
                ldap_pvt_thread_mutex_lock( &connections[i].c_mutex );
 
                /* connections_mutex and c_mutex are locked */
-               connection_closing( &connections[i] );
+               connection_closing( &connections[i], "slapd shutdown" );
                connection_close( &connections[i] );
 
                ldap_pvt_thread_mutex_unlock( &connections[i].c_mutex );
@@ -222,7 +224,7 @@ int connections_timeout_idle(time_t now)
 
                if( difftime( c->c_activitytime+global_idletimeout, now) < 0 ) {
                        /* close it */
-                       connection_closing( c );
+                       connection_closing( c, "idletimeout" );
                        connection_close( c );
                        i++;
                }
@@ -492,6 +494,7 @@ long connection_init(
        if ( flags == CONN_IS_CLIENT ) {
                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 );
                ldap_pvt_thread_mutex_unlock( &connections_mutex );
@@ -563,6 +566,7 @@ long connection_init(
 
        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;
        c->c_tls_ssf = 0;
@@ -625,6 +629,7 @@ connection_destroy( Connection *c )
        /* note: connections_mutex should be locked by caller */
        ber_socket_t    sd;
        unsigned long   connid;
+       const char              *close_reason;
 
        assert( connections != NULL );
        assert( c != NULL );
@@ -635,6 +640,7 @@ connection_destroy( Connection *c )
 
        /* 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);
 
@@ -672,9 +678,10 @@ connection_destroy( Connection *c )
        if ( sd != AC_SOCKET_INVALID ) {
                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 );
        }
 
        ber_sockbuf_free( c->c_sb );
@@ -688,6 +695,7 @@ connection_destroy( Connection *c )
 
        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
        /* call destructors, then constructors; avoids unnecessary allocation */
@@ -740,7 +748,7 @@ static void connection_abandon( Connection *c )
        }
 }
 
-void connection_closing( Connection *c )
+void connection_closing( Connection *c, const char *why )
 {
        assert( connections != NULL );
        assert( c != NULL );
@@ -758,6 +766,7 @@ void connection_closing( Connection *c )
                        c->c_connid, sd, 0 );
                /* update state to closing */
                c->c_conn_state = SLAP_C_CLOSING;
+               c->c_close_reason = why;
 
                /* don't listen on this port anymore */
                slapd_clr_read( sd, 1 );
@@ -773,6 +782,9 @@ void connection_closing( Connection *c )
                        ldap_pvt_thread_yield();
                        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;
        }
 }
 
@@ -1085,7 +1097,8 @@ operations_error:
        case LBER_ERROR:
        case LDAP_REQ_UNBIND:
                /* c_mutex is locked */
-               connection_closing( conn );
+               connection_closing(
+                       conn, tag == LDAP_REQ_UNBIND ? NULL : "operations error" );
                break;
 
        case LDAP_REQ_BIND:
@@ -1144,6 +1157,7 @@ void connection_client_stop(
        c->c_listener = NULL;
        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 );
 }
@@ -1209,7 +1223,7 @@ int connection_read(ber_socket_t s)
                                s, rc, c->c_connid );
                        c->c_needs_tls_accept = 0;
                        /* connections_mutex and c_mutex are locked */
-                       connection_closing( c );
+                       connection_closing( c, "TLS negotiation failure" );
 
 #if 0
                        /* Drain input before close, to allow SSL error codes
@@ -1247,6 +1261,9 @@ int connection_read(ber_socket_t s)
                                        "unable to get TLS client DN, error=%d id=%lu\n",
                                        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 );
                }
@@ -1281,7 +1298,7 @@ int connection_read(ber_socket_t s)
                                "error=%d id=%lu, closing\n",
                                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 );
                        ldap_pvt_thread_mutex_unlock( &connections_mutex );
@@ -1310,7 +1327,7 @@ int connection_read(ber_socket_t s)
                        "connection_read(%d): input error=%d id=%lu, closing.\n",
                        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 );
                ldap_pvt_thread_mutex_unlock( &connections_mutex );

diff --git a/servers/slapd/extended.c b/servers/slapd/extended.c
index 36c42e446ecfc61baa9f6526036eb8cda6ed6a4d..33a8a11807be07f392305a05ac79844c4f1b9b0c 100644 (file)
--- a/servers/slapd/extended.c
+++ b/servers/slapd/extended.c
@@ -166,6 +166,8 @@ do_extended(
 
        /* 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,
                        "manageDSAit control inappropriate" );
@@ -196,6 +198,8 @@ fe_extended( Operation *op, SlapReply *rs )
 
        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 );
                send_ldap_error( op, rs, LDAP_PROTOCOL_ERROR,
@@ -328,6 +332,9 @@ whoami_extop (
                return LDAP_PROTOCOL_ERROR;
        }
 
+       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,
                (struct berval *)&slap_EXOP_WHOAMI ) != LDAP_SUCCESS ) {

diff --git a/servers/slapd/passwd.c b/servers/slapd/passwd.c
index 738d9add84f0b5ec9970f8ee28d61cb549eced88..3d63e447fe2bf3bc7113e3102aa834c0c8ccfb8d 100644 (file)
--- a/servers/slapd/passwd.c
+++ b/servers/slapd/passwd.c
@@ -62,6 +62,8 @@ int passwd_extop(
        assert( ber_bvcmp( &slap_EXOP_MODIFY_PASSWD, &op->ore_reqoid ) == 0 );
 
        if( op->o_dn.bv_len == 0 ) {
+               Statslog( LDAP_DEBUG_STATS, "%s PASSMOD\n",
+                       op->o_log_prefix, 0, 0, 0, 0 );
                rs->sr_text = "only authenticated users may change passwords";
                return LDAP_STRONG_AUTH_REQUIRED;
        }
@@ -74,6 +76,16 @@ int passwd_extop(
        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, 0, 0, 0, 0 );
+       }
+
        if ( rs->sr_err != LDAP_SUCCESS ) {
                return rs->sr_err;
        }

diff --git a/servers/slapd/proto-slap.h b/servers/slapd/proto-slap.h
index d25d1f3e238fc75954d6092c55706c3c607f35d1..06ff2b2ea7a6ca6dbe353f788355ca5b7972b641 100644 (file)
--- a/servers/slapd/proto-slap.h
+++ b/servers/slapd/proto-slap.h
@@ -577,7 +577,8 @@ LDAP_SLAPD_F (long) connection_init LDAP_P((
        slap_ssf_t ssf,
        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 ))
        LDAP_GCCATTR((const));

diff --git a/servers/slapd/result.c b/servers/slapd/result.c
index d1e79bf3396021f4edf08e868b3d673e4ed964d0..1593e22bb0fc9d0db62590182c1771e428d6162e 100644 (file)
--- a/servers/slapd/result.c
+++ b/servers/slapd/result.c
@@ -189,7 +189,7 @@ static long send_ldap_ber(
                    err, sock_errstr(err), 0 );
 
                if ( err != EWOULDBLOCK && err != EAGAIN ) {
-                       connection_closing( conn );
+                       connection_closing( conn, "connection lost on write" );
 
                        ldap_pvt_thread_mutex_unlock( &conn->c_mutex );
                        ldap_pvt_thread_mutex_unlock( &conn->c_write_mutex );
@@ -613,7 +613,12 @@ send_ldap_sasl( Operation *op, SlapReply *rs )
        rs->sr_tag = req2res( op->o_tag );
        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 );
+       }
 }
 
 void
@@ -630,7 +635,12 @@ slap_send_ldap_extended( Operation *op, SlapReply *rs )
        rs->sr_tag = req2res( op->o_tag );
        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 );
+       }
 }
 
 void
@@ -644,7 +654,12 @@ slap_send_ldap_intermediate( Operation *op, SlapReply *rs )
                rs->sr_rspdata != NULL ? rs->sr_rspdata->bv_len : 0 );
        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 );
+       }
 }
 
 int

diff --git a/servers/slapd/slap.h b/servers/slapd/slap.h
index f1d55cab3628a8fc53bd71f9cdea230a4bc91e7a..130648a6636a9c1d39575532d3a7c54814ffa59f 100644 (file)
--- a/servers/slapd/slap.h
+++ b/servers/slapd/slap.h
@@ -2535,6 +2535,7 @@ typedef struct slap_conn {
        int                     c_struct_state; /* structure management state */
        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 */
        Sockbuf         *c_sb;                  /* ber connection stuff           */

diff --git a/servers/slapd/starttls.c b/servers/slapd/starttls.c
index 8864b03dd6def0f547f584bcf9eb90ca39328766..2ce38146c6ab14dc447d2cf43a976a8dfc805cdc 100644 (file)
--- a/servers/slapd/starttls.c
+++ b/servers/slapd/starttls.c
@@ -27,6 +27,9 @@ starttls_extop ( Operation *op, SlapReply *rs )
 {
        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 */
                rs->sr_text = "no request data expected";