cdp: Review of logging of cdp

cdp log at DEBUG level is too verbose
leading to an un-readable log and
rate-limiting. Instead of removing them
completely let's introduce a modparam
to enable the "heavy" debug.
By default it is not activated.

modules/cdp/mod.c

@@ -62,6 +62,7 @@ unsigned int latency_threshold = 500;			/**< default threshold for Diameter call
 unsigned int *latency_threshold_p = &latency_threshold;
 unsigned int workerq_latency_threshold = 100;	/**< default threshold for putting a task into worker queue (ms) */
 unsigned int workerq_length_threshold_percentage = 0;	/**< default threshold for worker queue length, percentage of max queue length - by default disabled */
+unsigned int debug_heavy = 0;
 
 extern dp_config *config; 				/**< DiameterPeer configuration structure */
 
@@ -166,6 +167,7 @@ static param_export_t cdp_params[] = {
 	{ "latency_threshold", 			PARAM_INT, 		&latency_threshold},		/**<threshold above which we will log*/
 	{ "workerq_latency_threshold", 	PARAM_INT, 		&workerq_latency_threshold},/**<time threshold putting job into queue*/
 	{ "workerq_length_threshold_percentage", 	PARAM_INT, 		&workerq_length_threshold_percentage},/**<queue length threshold - percentage of max queue length*/
+	{"debug_heavy", PARAM_INT, &debug_heavy},
 	{ 0, 0, 0 }
 };
 

modules/cdp/peermanager.c

@@ -135,17 +135,19 @@ void peer_manager_destroy()
  */
 void log_peer_list()
 {
-	/* must have lock on peer_list_lock when calling this!!! */
-	peer *p;
-	int i;
+	if (debug_heavy) {
+		/* must have lock on peer_list_lock when calling this!!! */
+		peer *p;
+		int i;
 
-	LM_DBG("--- Peer List: ---\n");
-	for(p = peer_list->head;p;p = p->next){
-		LM_DBG("State of peer: %s FQDN: %.*s Port: %d Is dynamic %c\n",dp_states[p->state],p->fqdn.len,p->fqdn.s,p->port,p->is_dynamic?'X':' ');
-		for(i=0;i<p->applications_cnt;i++)
-			LM_DBG("Application ID: %d, Application Vendor: %d \n",p->applications[i].id,p->applications[i].vendor);
+		LM_DBG("--- Peer List: ---\n");
+		for(p = peer_list->head;p;p = p->next){
+			LM_DBG("State of peer: %s FQDN: %.*s Port: %d Is dynamic %c\n",dp_states[p->state],p->fqdn.len,p->fqdn.s,p->port,p->is_dynamic?'X':' ');
+			for(i=0;i<p->applications_cnt;i++)
+				LM_DBG("Application ID: %d, Application Vendor: %d \n",p->applications[i].id,p->applications[i].vendor);
+		}
+		LM_DBG("------------------\n");
 	}
-	LM_DBG("------------------\n");
 }
 
 /**
@@ -310,7 +312,10 @@ int peer_timer(time_t now,void *ptr)
 						p->waitingDWA = 1;
 						Snd_DWR(p);
 						touch_peer(p);
-						LM_DBG("Inactivity on peer [%.*s], sending DWR... - if we don't get a reply, the peer will be closed\n", p->fqdn.len, p->fqdn.s);
+						if (debug_heavy)
+						{
+							LM_DBG("Inactivity on peer [%.*s], sending DWR... - if we don't get a reply, the peer will be closed\n", p->fqdn.len, p->fqdn.s);
+						}
 					}
 					break;
 					/* ignored states */

modules/cdp/peermanager.h

@@ -56,6 +56,8 @@ typedef struct {
 	peer *tail; /**< last peer in the list */
 } peer_list_t;
 
+extern unsigned int debug_heavy;
+
 int peer_manager_init(dp_config *config);
 
 void peer_manager_destroy();

modules/cdp/receiver.c

@@ -97,18 +97,20 @@ serviced_peer_t *serviced_peers=0; 	/**< pointer to the list of peers serviced b
  */
 static void log_serviced_peers()
 {
-	serviced_peer_t *sp;
+	if (debug_heavy) {
+		serviced_peer_t *sp;
 
-	LM_DBG("--- Receiver %s Serviced Peers: ---\n",
-			pt[process_no].desc);
-	for(sp=serviced_peers;sp;sp=sp->next){
-		LM_DBG(" Peer: %.*s  TCP Socket: %d  Recv.State: %d \n",
-				sp->p?sp->p->fqdn.len:0,
-				sp->p?sp->p->fqdn.s:0,
-				sp->tcp_socket,
-				sp->state);
+		LM_DBG("--- Receiver %s Serviced Peers: ---\n",
+				pt[process_no].desc);
+		for(sp=serviced_peers;sp;sp=sp->next){
+			LM_DBG(" Peer: %.*s  TCP Socket: %d  Recv.State: %d \n",
+					sp->p?sp->p->fqdn.len:0,
+					sp->p?sp->p->fqdn.s:0,
+					sp->tcp_socket,
+					sp->state);
+		}
+		LM_DBG("--------------------------------------------------------\n");
 	}
-	LM_DBG("--------------------------------------------------------\n");
 }
 
 

modules/cdp/receiver.h

@@ -81,6 +81,8 @@ typedef struct _serviced_peer_t {
 	struct _serviced_peer_t *prev; /**< last peer in the list */
 } serviced_peer_t;
 
+extern unsigned int debug_heavy;
+
 int receiver_init(peer *p);
 void receiver_process(peer *p);
 

modules/cdp/session.c

@@ -389,45 +389,47 @@ error:
 
 void cdp_sessions_log()
 {
-	int hash;
-	cdp_session_t *x;
-
-	LM_DBG("------- CDP Sessions ----------------\n");
-	for(hash=0;hash<sessions_hash_size;hash++){
-		AAASessionsLock(hash);
-		for(x = sessions[hash].head;x;x=x->next) {
-			LM_DBG(ANSI_GRAY" %3u. [%.*s] AppId [%d] Type [%d]\n",
-					hash,
-					x->id.len,x->id.s,
-					x->application_id,
-					x->type);
-			switch (x->type){
-				case AUTH_CLIENT_STATEFULL:
-				case AUTH_SERVER_STATEFULL:
-					LM_DBG("Auth State [%d] Timeout [%d] Lifetime [%d] Grace [%d] Generic [%p] Class [%d]\n",
-							x->u.auth.state,
-							(int)(x->u.auth.timeout-time(0)),
-							x->u.auth.lifetime?(int)(x->u.auth.lifetime-time(0)):-1,
-							(int)(x->u.auth.grace_period),
-							x->u.auth.generic_data,
-							x->u.auth.class);
-					break;
-				case ACCT_CC_CLIENT:
-					LM_DBG("CCAcct State [%d] Charging Active [%c (%d)s] Reserved Units(valid=%ds) [%d] Generic [%p]\n",
-							x->u.cc_acc.state,
-							(x->u.cc_acc.charging_start_time&&x->u.cc_acc.state!=ACC_CC_ST_DISCON)?'Y':'N',
-							x->u.cc_acc.charging_start_time?(int)((int)time(0) - (int)x->u.cc_acc.charging_start_time):-1,
-							x->u.cc_acc.reserved_units?(int)((int)x->u.cc_acc.last_reservation_request_time + x->u.cc_acc.reserved_units_validity_time) - (int)time(0):-1,
-							x->u.cc_acc.reserved_units,
-							x->u.cc_acc.generic_data);
-					break;
-				default:
-					break;
+	if (debug_heavy) {
+		int hash;
+		cdp_session_t *x;
+
+		LM_DBG("------- CDP Sessions ----------------\n");
+		for(hash=0;hash<sessions_hash_size;hash++){
+			AAASessionsLock(hash);
+			for(x = sessions[hash].head;x;x=x->next) {
+				LM_DBG(" %3u. [%.*s] AppId [%d] Type [%d]\n",
+						hash,
+						x->id.len,x->id.s,
+						x->application_id,
+						x->type);
+				switch (x->type){
+					case AUTH_CLIENT_STATEFULL:
+					case AUTH_SERVER_STATEFULL:
+						LM_DBG("Auth State [%d] Timeout [%d] Lifetime [%d] Grace [%d] Generic [%p] Class [%d]\n",
+								x->u.auth.state,
+								(int)(x->u.auth.timeout-time(0)),
+								x->u.auth.lifetime?(int)(x->u.auth.lifetime-time(0)):-1,
+								(int)(x->u.auth.grace_period),
+								x->u.auth.generic_data,
+								x->u.auth.class);
+						break;
+					case ACCT_CC_CLIENT:
+						LM_DBG("CCAcct State [%d] Charging Active [%c (%d)s] Reserved Units(valid=%ds) [%d] Generic [%p]\n",
+								x->u.cc_acc.state,
+								(x->u.cc_acc.charging_start_time&&x->u.cc_acc.state!=ACC_CC_ST_DISCON)?'Y':'N',
+								x->u.cc_acc.charging_start_time?(int)((int)time(0) - (int)x->u.cc_acc.charging_start_time):-1,
+								x->u.cc_acc.reserved_units?(int)((int)x->u.cc_acc.last_reservation_request_time + x->u.cc_acc.reserved_units_validity_time) - (int)time(0):-1,
+								x->u.cc_acc.reserved_units,
+								x->u.cc_acc.generic_data);
+						break;
+					default:
+						break;
+				}
 			}
+			AAASessionsUnlock(hash);
 		}
-		AAASessionsUnlock(hash);
+		LM_DBG("-------------------------------------\n");
 	}
-	LM_DBG("-------------------------------------\n");
 }
 
 int cdp_sessions_timer(time_t now, void* ptr)

modules/cdp/session.h

@@ -49,6 +49,8 @@
 #include "utils.h"
 #include "diameter.h"
 
+extern unsigned int debug_heavy;
+
 /** Function for callback on session events: timeout, etc. */
 typedef void (AAASessionCallback_f)(int event, void *session);
 

modules/cdp/tcp_accept.c

@@ -218,7 +218,7 @@ void accept_loop()
 
 		nready = select( max_sock+1, &listen_set, 0, 0, &timeout);
 		if (nready == 0){
-			LM_DBG("accept_loop(): No connection attempts\n");
+			if (debug_heavy) LM_DBG("accept_loop(): No connection attempts\n");
 			continue;
 		}
 		if (nready == -1) {

modules/cdp/tcp_accept.h

@@ -44,7 +44,7 @@
 #ifndef __TCP_ACCEPT_H
 #define __TCP_ACCEPT_H
 
-
+extern unsigned int debug_heavy;
 
 int create_socket(int listen_port,str bind_to,unsigned int *sock);
 

modules/cdp/transaction.c

@@ -191,7 +191,6 @@ void cdp_free_trans(cdp_trans_t *x)
 int cdp_trans_timer(time_t now, void* ptr)
 {
 	cdp_trans_t *x,*n;
-	LM_DBG("trans_timer(): taking care of diameter transactions...\n");
 	lock_get(trans_list->lock);
 	x = trans_list->head;
 	while(x)