From 05f2ac2583c791ddc5a9fe82bca2b02adda5178c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Kuzn=C3=ADk?= Date: Tue, 20 Jun 2017 13:00:31 +0100 Subject: [PATCH] Unify logging output --- servers/lloadd/backend.c | 3 +- servers/lloadd/bind.c | 8 ++--- servers/lloadd/client.c | 20 +++++++++++-- servers/lloadd/config.c | 16 +++++----- servers/lloadd/connection.c | 4 +-- servers/lloadd/daemon.c | 4 +-- servers/lloadd/operation.c | 39 +++++++++++++++++------- servers/lloadd/upstream.c | 59 +++++++++++++++++++++++++------------ 8 files changed, 104 insertions(+), 49 deletions(-) diff --git a/servers/lloadd/backend.c b/servers/lloadd/backend.c index 3bef93cfb3..3c2ee2190c 100644 --- a/servers/lloadd/backend.c +++ b/servers/lloadd/backend.c @@ -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 ); /* diff --git a/servers/lloadd/bind.c b/servers/lloadd/bind.c index 1f699fd2b1..4757024cc5 100644 --- a/servers/lloadd/bind.c +++ b/servers/lloadd/bind.c @@ -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 ) ) { diff --git a/servers/lloadd/client.c b/servers/lloadd/client.c index 239ca00f32..466d065d06 100644 --- a/servers/lloadd/client.c +++ b/servers/lloadd/client.c @@ -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 */ diff --git a/servers/lloadd/config.c b/servers/lloadd/config.c index 9189410897..dd62fb2881 100644 --- a/servers/lloadd/config.c +++ b/servers/lloadd/config.c @@ -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; diff --git a/servers/lloadd/connection.c b/servers/lloadd/connection.c index d8d46a5a89..e7b81b7607 100644 --- a/servers/lloadd/connection.c +++ b/servers/lloadd/connection.c @@ -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; } diff --git a/servers/lloadd/daemon.c b/servers/lloadd/daemon.c index b0e0d53680..b0f361efa0 100644 --- a/servers/lloadd/daemon.c +++ b/servers/lloadd/daemon.c @@ -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 ); } diff --git a/servers/lloadd/operation.c b/servers/lloadd/operation.c index 441d869518..0d0b2898b5 100644 --- a/servers/lloadd/operation.c +++ b/servers/lloadd/operation.c @@ -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; } diff --git a/servers/lloadd/upstream.c b/servers/lloadd/upstream.c index c9156782de..f6fbc5fa63 100644 --- a/servers/lloadd/upstream.c +++ b/servers/lloadd/upstream.c @@ -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;