Commit 05f2ac25 authored by Ondřej Kuzník's avatar Ondřej Kuzník Committed by Ondřej Kuzník
Browse files

Unify logging output

parent 873d6fa3
......@@ -138,7 +138,8 @@ backend_select( Operation *op )
( b->b_max_conn_pending == 0 ||
c->c_n_ops_executing < b->b_max_conn_pending ) ) {
Debug( LDAP_DEBUG_CONNS, "backend_select: "
"selected connection %lu for client %lu msgid=%d\n",
"selected connection connid=%lu for client "
"connid=%lu msgid=%d\n",
c->c_connid, op->o_client_connid, op->o_client_msgid );
/*
......
......@@ -93,8 +93,8 @@ request_bind( Operation *op )
LDAP_TAG_CONTROLS, BER_BV_OPTIONAL( &op->o_ctrls ) );
Debug( LDAP_DEBUG_TRACE, "request_bind: "
"added bind from client connid=%lu to upstream connid=%lu as "
"msgid=%d\n",
"added bind from client connid=%lu to upstream connid=%lu "
"as msgid=%d\n",
op->o_client_connid, op->o_upstream_connid, op->o_upstream_msgid );
if ( tavl_insert( &upstream->c_ops, op, operation_upstream_cmp,
avl_dup_error ) ) {
......@@ -222,8 +222,8 @@ request_bind_as_vc( Operation *op )
CONNECTION_LOCK(upstream);
Debug( LDAP_DEBUG_TRACE, "request_bind_as_vc: "
"added bind from client connid=%lu to upstream connid=%lu as VC "
"exop msgid=%d\n",
"added bind from client connid=%lu to upstream connid=%lu "
"as VC exop msgid=%d\n",
op->o_client_connid, op->o_upstream_connid, op->o_upstream_msgid );
if ( tavl_insert( &upstream->c_ops, op, operation_upstream_cmp,
avl_dup_error ) ) {
......
......@@ -41,12 +41,15 @@ client_read_cb( evutil_socket_t s, short what, void *arg )
CONNECTION_LOCK(c);
if ( !c->c_live ) {
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "client_read_cb: "
"suspended read event on a dead connid=%lu\n",
c->c_connid );
CONNECTION_UNLOCK(c);
return;
}
Debug( LDAP_DEBUG_CONNS, "client_read_cb: "
"connection %lu ready to read\n",
"connection connid=%lu ready to read\n",
c->c_connid );
ber = c->c_currentber;
......@@ -75,10 +78,16 @@ client_read_cb( evutil_socket_t s, short what, void *arg )
ber_free( ber, 1 );
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "client_read_cb: "
"suspended read event on dying connid=%lu\n",
c->c_connid );
CLIENT_DESTROY(c);
return;
}
event_add( c->c_read_event, NULL );
Debug( LDAP_DEBUG_CONNS, "client_read_cb: "
"re-enabled read event on connid=%lu\n",
c->c_connid );
CONNECTION_UNLOCK(c);
return;
}
......@@ -96,7 +105,11 @@ client_read_cb( evutil_socket_t s, short what, void *arg )
}
return;
}
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "client_read_cb: "
"suspended read event on connid=%lu\n",
c->c_connid );
CONNECTION_UNLOCK(c);
return;
......@@ -155,6 +168,9 @@ handle_requests( void *ctx, void *arg )
}
event_add( c->c_read_event, NULL );
Debug( LDAP_DEBUG_CONNS, "handle_requests: "
"re-enabled read event on connid=%lu\n",
c->c_connid );
CLIENT_UNLOCK_OR_DESTROY(c);
return NULL;
}
......@@ -230,7 +246,7 @@ client_write_cb( evutil_socket_t s, short what, void *arg )
ldap_pvt_thread_mutex_lock( &c->c_io_mutex );
Debug( LDAP_DEBUG_CONNS, "client_write_cb: "
"have something to write to client %lu\n",
"have something to write to client connid=%lu\n",
c->c_connid );
/* We might have been beaten to flushing the data by another thread */
......
......@@ -396,7 +396,7 @@ config_generic( ConfigArgs *c )
snprintf( c->cr_msg, sizeof(c->cr_msg),
"threads=%d smaller than minimum value 2",
c->value_int );
Debug( LDAP_DEBUG_ANY, "%s: %s.\n", c->log, c->cr_msg );
Debug( LDAP_DEBUG_ANY, "%s: %s\n", c->log, c->cr_msg );
return 1;
} else if ( c->value_int > 2 * SLAP_MAX_WORKER_THREADS ) {
......@@ -405,7 +405,7 @@ config_generic( ConfigArgs *c )
"(2*%d=%d); YMMV",
c->value_int, SLAP_MAX_WORKER_THREADS,
2 * SLAP_MAX_WORKER_THREADS );
Debug( LDAP_DEBUG_ANY, "%s: %s.\n", c->log, c->cr_msg );
Debug( LDAP_DEBUG_ANY, "%s: %s\n", c->log, c->cr_msg );
}
if ( slapMode & SLAP_SERVER_MODE )
ldap_pvt_thread_pool_maxthreads(
......@@ -418,7 +418,7 @@ config_generic( ConfigArgs *c )
snprintf( c->cr_msg, sizeof(c->cr_msg),
"threadqueues=%d smaller than minimum value 1",
c->value_int );
Debug( LDAP_DEBUG_ANY, "%s: %s.\n", c->log, c->cr_msg );
Debug( LDAP_DEBUG_ANY, "%s: %s\n", c->log, c->cr_msg );
return 1;
}
if ( slapMode & SLAP_SERVER_MODE )
......@@ -449,14 +449,14 @@ config_generic( ConfigArgs *c )
if ( c->value_int < 0 ) {
snprintf( c->cr_msg, sizeof(c->cr_msg),
"max_pdus_per_cycle=%d invalid", c->value_int );
Debug( LDAP_DEBUG_ANY, "%s: %s.\n", c->log, c->cr_msg );
Debug( LDAP_DEBUG_ANY, "%s: %s\n", c->log, c->cr_msg );
return 1;
}
slap_conn_max_pdus_per_cycle = c->value_int;
break;
default:
Debug( LDAP_DEBUG_ANY, "%s: unknown CFG_TYPE %d.\n",
Debug( LDAP_DEBUG_ANY, "%s: unknown CFG_TYPE %d\n",
c->log, c->type );
return 1;
}
......@@ -1324,7 +1324,7 @@ config_check_vals( ConfigTable *Conf, ConfigArgs *c, int check_only )
c->argv[0], Conf->what );
ignored = "";
Debug( LDAP_DEBUG_CONFIG|LDAP_DEBUG_NONE, "%s: %s%s.\n",
Debug( LDAP_DEBUG_CONFIG|LDAP_DEBUG_NONE, "%s: %s%s\n",
c->log, c->cr_msg, ignored );
return ARG_BAD_CONF;
}
......@@ -1647,7 +1647,7 @@ read_config_file(
}
if ( c->argc < 1 ) {
Debug( LDAP_DEBUG_ANY, "%s: bad config line.\n", c->log );
Debug( LDAP_DEBUG_ANY, "%s: bad config line\n", c->log );
rc = 1;
goto done;
}
......@@ -1674,7 +1674,7 @@ read_config_file(
} else {
Debug( LDAP_DEBUG_ANY, "%s: unknown directive "
"<%s> outside backend info and database definitions.\n",
"<%s> outside backend info and database definitions\n",
c->log, *c->argv );
rc = 1;
goto done;
......
......@@ -55,7 +55,7 @@ connection_destroy( Connection *c )
{
assert( c );
Debug( LDAP_DEBUG_CONNS, "connection_destroy: "
"destroying connection %lu.\n",
"destroying connection connid=%lu\n",
c->c_connid );
assert( c->c_live == 0 );
......@@ -94,7 +94,7 @@ connection_init( ber_socket_t s, const char *peername, int flags )
if ( s == AC_SOCKET_INVALID ) {
Debug( LDAP_DEBUG_ANY, "connection_init: "
"init of socket fd=%ld invalid.\n",
"init of socket fd=%ld invalid\n",
(long)s );
return NULL;
}
......
......@@ -736,7 +736,7 @@ slapd_daemon_init( const char *urls )
if ( u == NULL || u[0] == NULL ) {
Debug( LDAP_DEBUG_ANY, "slapd_daemon_init: "
"no urls (%s) provided.\n",
"no urls (%s) provided\n",
urls );
if ( u ) ldap_charray_free( u );
return -1;
......@@ -1003,7 +1003,7 @@ slap_listener(
if ( !c ) {
Debug( LDAP_DEBUG_ANY, "slap_listener: "
"client_init(%ld, %s, %s) failed.\n",
"client_init(%ld, %s, %s) failed\n",
(long)s, peername, sl->sl_name.bv_val );
slapd_close( s );
}
......
......@@ -186,8 +186,9 @@ operation_destroy_from_client( Operation *op )
*/
if ( !detach_client && race_state == SLAP_OP_FREEING_UPSTREAM ) {
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_client: "
"op=%p lost race, increasing client refcnt c=%p\n",
op, client );
"op=%p lost race, increased client refcnt connid=%lu "
"to refcnt=%d\n",
op, client->c_connid, client->c_refcnt );
CONNECTION_LOCK(client);
} else {
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_client: "
......@@ -216,8 +217,8 @@ operation_destroy_from_client( Operation *op )
*/
upstream->c_refcnt--;
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_client: "
"op=%p other side lost race with us\n",
op );
"op=%p other side lost race with us, upstream connid=%lu\n",
op, upstream->c_connid );
}
ldap_pvt_thread_mutex_unlock( &op->o_mutex );
......@@ -330,8 +331,9 @@ operation_destroy_from_upstream( Operation *op )
*/
if ( !detach_upstream && race_state == SLAP_OP_FREEING_CLIENT ) {
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_upstream: "
"op=%p lost race, increasing upstream refcnt c=%p\n",
op, upstream );
"op=%p lost race, increased upstream refcnt connid=%lu "
"to refcnt=%d\n",
op, upstream->c_connid, upstream->c_refcnt );
CONNECTION_LOCK(upstream);
} else {
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_upstream: "
......@@ -360,8 +362,8 @@ operation_destroy_from_upstream( Operation *op )
*/
client->c_refcnt--;
Debug( LDAP_DEBUG_TRACE, "operation_destroy_from_upstream: "
"op=%p other side lost race with us\n",
op );
"op=%p other side lost race with us, client connid=%lu\n",
op, client->c_connid );
}
ldap_pvt_thread_mutex_unlock( &op->o_mutex );
......@@ -431,8 +433,8 @@ operation_init( Connection *c, BerElement *ber )
rc = tavl_insert( &c->c_ops, op, operation_client_cmp, avl_dup_error );
if ( rc ) {
Debug( LDAP_DEBUG_PACKETS, "operation_init: "
"several operations with same msgid=%d in-flight from client "
"%lu\n",
"several operations with same msgid=%d in-flight "
"from client connid=%lu\n",
op->o_client_msgid, op->o_client_connid );
goto fail;
}
......@@ -560,8 +562,16 @@ request_abandon( Connection *c, Operation *op )
request = tavl_find( c->c_ops, &needle, operation_client_cmp );
if ( !request ) {
Debug( LDAP_DEBUG_TRACE, "request_abandon: "
"connid=%lu msgid=%d requests abandon of an operation "
"msgid=%d not being processed anymore\n",
c->c_connid, op->o_client_msgid, needle.o_client_msgid );
goto done;
}
Debug( LDAP_DEBUG_TRACE, "request_abandon: "
"connid=%lu msgid=%d abandoning %s msgid=%d\n",
c->c_connid, op->o_client_msgid, slap_msgtype2str( request->o_tag ),
needle.o_client_msgid );
CONNECTION_UNLOCK_INCREF(c);
operation_abandon( request );
......@@ -584,7 +594,7 @@ operation_send_reject(
int found;
Debug( LDAP_DEBUG_TRACE, "operation_send_reject: "
"rejecting %s from client %lu with message: \"%s\"\n",
"rejecting %s from client connid=%lu with message: \"%s\"\n",
slap_msgtype2str( op->o_tag ), op->o_client_connid, msg );
ldap_pvt_thread_mutex_lock( &operation_mutex );
......@@ -595,6 +605,9 @@ operation_send_reject(
* client is dead, it must have been the upstream */
assert( c );
CONNECTION_LOCK(c);
Debug( LDAP_DEBUG_TRACE, "operation_send_reject: "
"not sending msgid=%d, client connid=%lu is dead\n",
op->o_client_msgid, op->o_client_connid );
ldap_pvt_thread_mutex_unlock( &operation_mutex );
operation_destroy_from_upstream( op );
UPSTREAM_UNLOCK_OR_DESTROY(c);
......@@ -605,6 +618,10 @@ operation_send_reject(
found = ( tavl_delete( &c->c_ops, op, operation_client_cmp ) == op );
if ( !found && !send_anyway ) {
Debug( LDAP_DEBUG_TRACE, "operation_send_reject: "
"msgid=%d not scheduled for client connid=%lu anymore, "
"not sending\n",
op->o_client_msgid, c->c_connid );
goto done;
}
......
......@@ -41,7 +41,7 @@ forward_response( Operation *op, BerElement *ber )
}
Debug( LDAP_DEBUG_CONNS, "forward_response: "
"%s to client %lu request #%d\n",
"%s to client connid=%lu request msgid=%d\n",
slap_msgtype2str( response_tag ), op->o_client_connid,
op->o_client_msgid );
......@@ -72,8 +72,9 @@ forward_final_response( Operation *op, BerElement *ber )
int rc;
Debug( LDAP_DEBUG_CONNS, "forward_final_response: "
"finishing up with request #%d for client %lu\n",
op->o_client_msgid, op->o_client_connid );
"connid=%lu msgid=%d finishing up with a request for "
"client connid=%lu\n",
op->o_upstream_connid, op->o_upstream_msgid, op->o_client_connid );
rc = forward_response( op, ber );
CONNECTION_LOCK_DECREF(op->o_upstream);
operation_destroy_from_upstream( op );
......@@ -106,7 +107,8 @@ handle_bind_response( Operation *op, BerElement *ber )
}
Debug( LDAP_DEBUG_CONNS, "handle_bind_response: "
"received response for bind request by client %lu, result=%d\n",
"received response for bind request by client connid=%lu, "
"result=%d\n",
op->o_client_connid, result );
CONNECTION_LOCK(c);
......@@ -169,7 +171,8 @@ handle_vc_bind_response( Operation *op, BerElement *ber )
CONNECTION_LOCK(upstream);
b = (Backend *)upstream->c_private;
Debug( LDAP_DEBUG_ANY, "VC extended operation not supported on backend %s\n",
Debug( LDAP_DEBUG_ANY, "handle_vc_bind_response: "
"VC extended operation not supported on backend %s\n",
b->b_uri.bv_val );
CONNECTION_UNLOCK(upstream);
}
......@@ -177,7 +180,8 @@ handle_vc_bind_response( Operation *op, BerElement *ber )
CONNECTION_LOCK(c);
Debug( LDAP_DEBUG_CONNS, "handle_vc_bind_response: "
"received response for bind request by client %lu, result=%d\n",
"received response for bind request by client connid=%lu, "
"result=%d\n",
c->c_connid, result );
if ( tag == LDAP_TAG_EXOP_VERIFY_CREDENTIALS_COOKIE ) {
......@@ -274,7 +278,7 @@ handle_unsolicited( Connection *c, BerElement *ber )
c->c_state = SLAP_C_CLOSING;
Debug( LDAP_DEBUG_CONNS, "handle_unsolicited: "
"teardown for upstream connection %lu\n",
"teardown for upstream connection connid=%lu\n",
c->c_connid );
UPSTREAM_DESTROY(c);
......@@ -372,13 +376,14 @@ handle_one_response( Connection *c )
}
if ( op ) {
Debug( LDAP_DEBUG_TRACE, "handle_one_response: "
"upstream=%lu, processing response for client connid=%lu, "
"msgid=%d\n",
"upstream connid=%lu, processing response for "
"client connid=%lu, msgid=%d\n",
c->c_connid, op->o_client_connid, op->o_client_msgid );
} else {
tag = ber_peek_tag( ber, &len );
Debug( LDAP_DEBUG_TRACE, "handle_one_response: "
"upstream=%lu, %s, msgid=%d not for a pending operation\n",
Debug( LDAP_DEBUG_STATS2, "handle_one_response: "
"upstream connid=%lu, %s, msgid=%d not for a pending "
"operation\n",
c->c_connid, slap_msgtype2str( tag ), needle.o_upstream_msgid );
}
......@@ -415,9 +420,10 @@ handle_one_response( Connection *c )
fail:
if ( rc ) {
Debug( LDAP_DEBUG_ANY, "handle_one_response: "
"error on processing a response on upstream connection %ld\n",
c->c_connid );
Debug( LDAP_DEBUG_STATS, "handle_one_response: "
"error on processing a response (%s) on upstream connection "
"connid=%ld, tag=%lx\n",
slap_msgtype2str( tag ), c->c_connid, tag );
UPSTREAM_DESTROY(c);
}
/* We leave the connection locked */
......@@ -487,6 +493,9 @@ handle_responses( void *ctx, void *arg )
}
event_add( c->c_read_event, NULL );
Debug( LDAP_DEBUG_CONNS, "handle_responses: "
"re-enabled read event on connid=%lu\n",
c->c_connid );
UPSTREAM_UNLOCK_OR_DESTROY(c);
return NULL;
}
......@@ -509,11 +518,14 @@ upstream_read_cb( evutil_socket_t s, short what, void *arg )
CONNECTION_LOCK(c);
if ( !c->c_live ) {
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "upstream_read_cb: "
"suspended read event on a dead connid=%lu\n",
c->c_connid );
CONNECTION_UNLOCK(c);
return;
}
Debug( LDAP_DEBUG_CONNS, "upstream_read_cb: "
"connection %lu ready to read\n",
"connection connid=%lu ready to read\n",
c->c_connid );
ber = c->c_currentber;
......@@ -542,10 +554,16 @@ upstream_read_cb( evutil_socket_t s, short what, void *arg )
ber_free( ber, 1 );
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "upstream_read_cb: "
"suspended read event on dying connid=%lu\n",
c->c_connid );
UPSTREAM_DESTROY(c);
return;
}
event_add( c->c_read_event, NULL );
Debug( LDAP_DEBUG_CONNS, "upstream_read_cb: "
"re-enabled read event on connid=%lu\n",
c->c_connid );
CONNECTION_UNLOCK(c);
return;
}
......@@ -580,7 +598,7 @@ upstream_finish( Connection *c )
evutil_socket_t s = c->c_fd;
Debug( LDAP_DEBUG_CONNS, "upstream_finish: "
"connection %lu is ready for use\n",
"connection connid=%lu is ready for use\n",
c->c_connid );
base = slap_get_base( s );
......@@ -615,7 +633,7 @@ upstream_bind_cb( evutil_socket_t s, short what, void *arg )
CONNECTION_LOCK(c);
Debug( LDAP_DEBUG_CONNS, "upstream_bind_cb: "
"connection %lu ready to read\n",
"connection connid=%lu ready to read\n",
c->c_connid );
ber = c->c_currentber;
......@@ -689,6 +707,9 @@ upstream_bind_cb( evutil_socket_t s, short what, void *arg )
fail:
event_del( c->c_read_event );
Debug( LDAP_DEBUG_CONNS, "upstream_bind_cb: "
"suspended read event on dying connid=%lu\n",
c->c_connid );
ber_free( ber, 1 );
UPSTREAM_DESTROY(c);
}
......@@ -710,7 +731,7 @@ upstream_write_cb( evutil_socket_t s, short what, void *arg )
ldap_pvt_thread_mutex_lock( &c->c_io_mutex );
Debug( LDAP_DEBUG_CONNS, "upstream_write_cb: "
"have something to write to upstream %lu\n",
"have something to write to upstream connid=%lu\n",
c->c_connid );
/* We might have been beaten to flushing the data by another thread */
......@@ -893,7 +914,7 @@ upstream_destroy( Connection *c )
long freed, executing;
Debug( LDAP_DEBUG_CONNS, "upstream_destroy: "
"freeing connection %lu\n",
"freeing connection connid=%lu\n",
c->c_connid );
c->c_state = SLAP_C_INVALID;
......
Supports Markdown
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