Commit 9873eb7a authored by Hallvard Furuseth's avatar Hallvard Furuseth
Browse files

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.
parent a222469d
......@@ -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;
......
......@@ -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;
......
......@@ -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 ) {
......
......@@ -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 );
......
......@@ -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 ) {
......
......@@ -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;
}
......
......@@ -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));
......
......@@ -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
......
......@@ -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 */
......
......@@ -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";
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment