From 9873eb7ab0c9d96b25a5785fc0b448ad20d6394e Mon Sep 17 00:00:00 2001 From: Hallvard Furuseth Date: Sun, 14 Aug 2005 00:14:58 +0000 Subject: [PATCH] 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. --- servers/slapd/abandon.c | 3 +++ servers/slapd/back-ldap/config.c | 3 +++ servers/slapd/cancel.c | 3 +++ servers/slapd/connection.c | 37 +++++++++++++++++++++++--------- servers/slapd/extended.c | 7 ++++++ servers/slapd/passwd.c | 12 +++++++++++ servers/slapd/proto-slap.h | 3 ++- servers/slapd/result.c | 23 ++++++++++++++++---- servers/slapd/slap.h | 1 + servers/slapd/starttls.c | 3 +++ 10 files changed, 80 insertions(+), 15 deletions(-) diff --git a/servers/slapd/abandon.c b/servers/slapd/abandon.c index df2f937f49..006a8c8f39 100644 --- 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 cf8aa6642f..7968dc5331 100644 --- 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 c1b288c6d5..16289a9d47 100644 --- 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 56c02c2f7a..217ba8da08 100644 --- 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 36c42e446e..33a8a11807 100644 --- 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 738d9add84..3d63e447fe 100644 --- 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 d25d1f3e23..06ff2b2ea7 100644 --- 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 d1e79bf339..1593e22bb0 100644 --- 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 f1d55cab36..130648a663 100644 --- 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 8864b03dd6..2ce38146c6 100644 --- 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"; -- 2.39.5