Unify logging output

diff --git a/servers/lloadd/backend.c b/servers/lloadd/backend.c
index 3bef93cfb3cfee91a8498b3885d83ca3d666b57d..3c2ee2190cf7c44315fb6e0bbaf34c6c103c56fb 100644 (file)
--- 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 1f699fd2b1061c463a20d06d7994e59dbeb4fa30..4757024cc5eccf90a3fdce2c164d054a749a556c 100644 (file)
--- 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 239ca00f327fe679419fa06e7e146db99395bc76..466d065d06d2ac6f195ae7aa97fa01b5929c66f5 100644 (file)
--- 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 9189410897c259e976d346292aa34758dbafca76..dd62fb2881d82b452c3de76843fb3f3a94b9408d 100644 (file)
--- 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 d8d46a5a89626209ea63cb44800e3984f91d0f9d..e7b81b7607f3ca459201cab30e42f2437ef5c5a1 100644 (file)
--- 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 b0e0d53680d50b4ff50534a72f77f3a953902705..b0f361efa0c179f65efd21080688815449867f38 100644 (file)
--- 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 441d869518c7c40e4fbd2a9f59c92df12adb0df8..0d0b2898b53438d97ff3e78b111a4f84f972d4c2 100644 (file)
--- 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 c9156782debba33877365d1422dde4f306144706..f6fbc5fa633153646174bee772385bf69add9fe7 100644 (file)
--- 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;