Merge pull request #692 from athonet-open/refactor_cdp_log

Refactor cdp log

modules/cdp/doc/cdp_admin.xml

@@ -144,6 +144,25 @@ modparam("cdp", "workerq_length_threshold_percentage", 25)
 	</programlisting>
       </example>
     </section>
+ <section>
+      <title>debug_heavy (int)</title>
+
+      <para>Flag to enable a more verbose log, which tells you
+		more details about peers. This is disabled by default
+		because it brings to a log too much verbose in DBG mode
+		Can be enabled upon needs</para>
+
+      <para><emphasis> Default value is <quote>0</quote>. </emphasis></para>
+
+      <example>
+        <title>Set <varname>debug_heavy</varname> parameter</title>
+
+        <programlisting format="linespecific">...
+modparam("cdp", "debug_heavy", 1)
+...
+	</programlisting>
+      </example>
+ </section>
   </section>
 
   <section>

modules/cdp/globals.h

@@ -64,14 +64,4 @@ extern gen_lock_t *shutdownx_lock; /**< lock used on shutdown				*/
 
 extern pid_t *dp_first_pid;		/**< first pid that we started from		*/
 
-/* ANSI Terminal colors */
-#define ANSI_GRAY		"\033[01;30m"
-#define ANSI_BLINK_RED 	"\033[00;31m"
-#define ANSI_RED 		"\033[01;31m"
-#define ANSI_GREEN		"\033[01;32m"
-#define ANSI_YELLOW 	"\033[01;33m"
-#define ANSI_BLUE 		"\033[01;34m"
-#define ANSI_MAGENTA	"\033[01;35m"
-#define ANSI_CYAN		"\033[01;36m"
-#define ANSI_WHITE		"\033[01;37m"
 #endif

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(ANSI_GREEN" S["ANSI_YELLOW"%s"ANSI_GREEN"] "ANSI_BLUE"%.*s:%d"ANSI_GREEN" D["ANSI_RED"%c"ANSI_GREEN"]\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(ANSI_YELLOW"\t [%d,%d]"ANSI_GREEN"\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");
 }
 
 /**
@@ -275,7 +277,7 @@ int peer_timer(time_t now,void *ptr)
 		}
 
 		if (p->activity+config->tc<=now){
-			LM_DBG("peer_timer(): Peer %.*s \tState %d \n",p->fqdn.len,p->fqdn.s,p->state);
+			LM_DBG("peer_timer(): Peer %.*s State %d \n",p->fqdn.len,p->fqdn.s,p->state);
 			switch (p->state){
 				/* initiating connection */
 				case Closed:
@@ -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/peerstatemachine.c

@@ -86,7 +86,7 @@ int sm_process(peer *p,peer_event_t event,AAAMessage *msg,int peer_locked,int so
 	int msg_received=0;
 
 	if (!peer_locked) lock_get(p->lock);
-	LM_DBG("sm_process(): Peer %.*s \tState %s \tEvent %s\n",
+	LM_DBG("sm_process(): Peer %.*s State %s Event %s\n",
 			p->fqdn.len,p->fqdn.s,dp_states[p->state],dp_events[event-101]);
 
 	switch (p->state){

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 ["ANSI_BLUE"%s"ANSI_GREEN"] Serviced Peers: ---\n",
-			pt[process_no].desc);
-	for(sp=serviced_peers;sp;sp=sp->next){
-		LM_DBG(ANSI_GREEN" Peer: ["ANSI_YELLOW"%.*s"ANSI_GREEN"]  TCP Socket: ["ANSI_YELLOW"%d"ANSI_GREEN"] Recv.State: ["ANSI_YELLOW"%d"ANSI_GREEN"]\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");
 }
 
 
@@ -857,7 +859,7 @@ int peer_connect(peer *p)
 	{
 		if (getnameinfo(ainfo->ai_addr,ainfo->ai_addrlen,
 					host,256,serv,256,NI_NUMERICHOST|NI_NUMERICSERV)==0){
-			LM_WARN("peer_connect(): Trying to connect to %s port %s\n",
+			LM_INFO("peer_connect(): Trying to connect to %s port %s\n",
 					host,serv);
 		}
 
@@ -876,11 +878,11 @@ int peer_connect(peer *p)
 			error = getaddrinfo(p->src_addr.s, NULL, &hints, &sainfo);
 
 			if (error!=0){
-				LM_WARN("peer_connect(): error getting client socket on %.*s:%s\n",
+				LM_ERR("peer_connect(): error getting client socket on %.*s:%s\n",
 						p->src_addr.len,p->src_addr.s,gai_strerror(error));
 			} else {
 				if (bind(sock, sainfo->ai_addr, sainfo->ai_addrlen )) {
-					LM_WARN("peer_connect(): error opening client socket on %.*s:%s\n",
+					LM_ERR("peer_connect(): error opening client socket on %.*s:%s\n",
 							p->src_addr.len,p->src_addr.s,strerror(errno));
 				}
 			}
@@ -905,18 +907,18 @@ int peer_connect(peer *p)
 						int  valopt;
 						getsockopt(sock, SOL_SOCKET, SO_ERROR, (void*)(&valopt), &lon);
 						if (valopt) {
-							LM_WARN("peer_connect(): Error opening connection to to %s port %s >%s\n",host,serv,strerror(valopt));
+							LM_ERR("peer_connect(): Error opening connection to to %s port %s >%s\n",host,serv,strerror(valopt));
 							close(sock);
 							continue;
 						}
 					}else{
-						LM_WARN("peer_connect(): Timeout or error opening connection to to %s port %s >%s\n",host,serv,strerror(errno));
+						LM_ERR("peer_connect(): Timeout or error opening connection to to %s port %s >%s\n",host,serv,strerror(errno));
 						close(sock);
 						continue;
 					}
 				}
 			}else{
-				LM_WARN("peer_connect(): Error opening connection to to %s port %s >%s\n",host,serv,strerror(errno));
+				LM_ERR("peer_connect(): Error opening connection to to %s port %s >%s\n",host,serv,strerror(errno));
 				close(sock);
 				continue;
 			}

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(ANSI_MAGENTA"------- CDP Sessions ----------------\n"ANSI_GREEN);
-	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(ANSI_GRAY"\tAuth 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(ANSI_GRAY"\tCCAcct 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(ANSI_MAGENTA"-------------------------------------\n"ANSI_GREEN);
 }
 
 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)