mrp: debug updates

This commit updates debug output (no functional changes)
- adds mrpd_log_printf() which timestamps all output messages
- fixes debug strings in mrp_state_string()
- adds logging of timer start/stop operations
- renames MRP event debug strings to match those spec'd in 802.1Q
- update debug output update for client SND and RECV messages

9 files changed, 225 insertions, 86 deletions

diff --git a/daemons/mrpd/mmrp.c b/daemons/mrpd/mmrp.c
index 9a3d3d53..85c9afb3 100644
--- a/daemons/mrpd/mmrp.c
+++ b/daemons/mrpd/mmrp.c
@@ -205,7 +205,7 @@ int mmrp_event(int event, struct mmrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MMRP
-			printf("MMRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MMRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MMRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TXLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -224,7 +224,7 @@ int mmrp_event(int event, struct mmrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MMRP
-			printf("MMRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MMRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MMRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_RLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -241,7 +241,7 @@ int mmrp_event(int event, struct mmrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MMRP
-			printf("MMRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MMRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MMRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TX);
 			attrib = attrib->next;
@@ -268,7 +268,7 @@ int mmrp_event(int event, struct mmrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MMRP
-			printf("MMRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MMRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MMRP_db->mrp_db), &(attrib->applicant),
 					  MRP_EVENT_PERIODIC);
@@ -300,7 +300,7 @@ int mmrp_event(int event, struct mmrp_attribute *rattrib)
 		}
 
 #if LOG_MMRP
-		printf("MMRP -> mrp_applicant_fsm\n");
+		mrpd_log_printf("MMRP -> mrp_applicant_fsm\n");
 #endif
 		mrp_applicant_fsm(&(MMRP_db->mrp_db), &(attrib->applicant), event);
 		/* remap local requests into registrar events */
@@ -1292,6 +1292,9 @@ int mmrp_txpdu(void)
 	msgbuf_len = mrpdu_msg_ptr - msgbuf;
 
 	bytes = mrpd_send(mmrp_socket, msgbuf, msgbuf_len, 0);
+#if LOG_MMRP
+	mrpd_log_printf("MMRP send PDU\n");
+#endif
 	if (bytes <= 0)
 		goto out;
 
@@ -1529,13 +1532,13 @@ int mmrp_recv_cmd(char *buf, int buflen, struct sockaddr_in *client)
 {
 	int rc;
 	int err_index;
-	char respbuf[8];
+	char respbuf[12];
 	int mrp_event;
 	uint8_t svcreq_param;
 	uint8_t macvec_param[6];
 
 	if (NULL == MMRP_db) {
-		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s", buf);
+		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s\n", buf);
 		mrpd_send_ctl_msg(client, respbuf, sizeof(respbuf));
 		goto out;
 	}
@@ -1682,8 +1685,6 @@ int mmrp_init(int mmrp_enable)
 	mmrp_socket = INVALID_SOCKET;
 	/* XXX */
 	return -1;
-
-	return 0;
 }
 
 int mmrp_reclaim(void)
diff --git a/daemons/mrpd/mrp.c b/daemons/mrpd/mrp.c
index 6a86e155..64cd169a 100644
--- a/daemons/mrpd/mrp.c
+++ b/daemons/mrpd/mrp.c
@@ -48,47 +48,47 @@ static char *mrp_event_string(int e)
 {
 	switch (e) {
 	case MRP_EVENT_BEGIN:
-		return "BEGIN";
+		return "Begin!";
 	case MRP_EVENT_NEW:
-		return "NEW";
+		return "New!";
 	case MRP_EVENT_JOIN:
-		return "JOIN";
+		return "Join!";
 	case MRP_EVENT_LV:
-		return "LV";
+		return "Lv!";
 	case MRP_EVENT_TX:
-		return "TX";
+		return "tx!";
 	case MRP_EVENT_TXLA:
-		return "TXLA";
+		return "txLA!";
 	case MRP_EVENT_TXLAF:
-		return "TXLAF";
+		return "txLAF!";
 	case MRP_EVENT_RNEW:
-		return "RNEW";
+		return "rNew!";
 	case MRP_EVENT_RJOININ:
-		return "RJOININ";
+		return "rJoinIn!";
 	case MRP_EVENT_RIN:
-		return "RIN";
+		return "rIn!";
 	case MRP_EVENT_RJOINMT:
-		return "RJOINMT";
+		return "rJoinMt!";
 	case MRP_EVENT_RMT:
-		return "RMT";
+		return "rMt!";
 	case MRP_EVENT_RLV:
-		return "RLV";
+		return "rLv!";
 	case MRP_EVENT_RLA:
-		return "RLA";
+		return "rLA!";
 	case MRP_EVENT_FLUSH:
-		return "FLUSH";
+		return "Flush!";
 	case MRP_EVENT_REDECLARE:
-		return "REDECLARE";
+		return "Re-Declare!";
 	case MRP_EVENT_PERIODIC:
-		return "PERIODIC";
+		return "periodic!";
 	case MRP_EVENT_PERIODIC_ENABLE:
 		return "ENABLE";
 	case MRP_EVENT_PERIODIC_DISABLE:
 		return "DISABLE";
 	case MRP_EVENT_LVTIMER:
-		return "LVTIMER";
+		return "leavetimer!";
 	case MRP_EVENT_LVATIMER:
-		return "LVATIMER";
+		return "leavealltimer!";
 	default:
 		return "UNKNOWN";
 	}
@@ -100,39 +100,49 @@ static char *mrp_state_string(int s)
 	case MRP_VO_STATE:
 		return "VO";
 	case MRP_VP_STATE:
-		return "VO";
+		return "VP";
 	case MRP_VN_STATE:
-		return "VO";
+		return "VN";
 	case MRP_AN_STATE:
-		return "VO";
+		return "AN";
 	case MRP_AA_STATE:
-		return "VO";
+		return "AA";
 	case MRP_QA_STATE:
-		return "VO";
+		return "QA";
 	case MRP_LA_STATE:
-		return "VO";
+		return "LA";
 	case MRP_AO_STATE:
-		return "VO";
+		return "AO";
 	case MRP_QO_STATE:
-		return "VO";
+		return "QO";
 	case MRP_AP_STATE:
-		return "VO";
+		return "AP";
 	case MRP_QP_STATE:
-		return "VO";
+		return "QP";
 	case MRP_LO_STATE:
-		return "VO";
+		return "LO";
 
 	case MRP_IN_STATE:
-		return "VO";
+		return "IN";
 	case MRP_LV_STATE:
-		return "VO";
+		return "LV";
 	case MRP_MT_STATE:
-		return "VO";
+		return "MT";
 	default:
-		return"??";
+		return "??";
 	}
 }
 
+static char *mrp_lvatimer_state_string(int s)
+{
+	if (s == MRP_TIMER_PASSIVE)
+		return "PASSIVE";
+	else if (s == MRP_TIMER_ACTIVE)
+		return "ACTIVE";
+	else
+		return "??";
+}
+
 static int client_lookup(client_t * list, struct sockaddr_in *newclient)
 {
 	client_t *client_item;
@@ -229,11 +239,17 @@ int mrp_jointimer_start(struct mrp_database *mrp_db)
 	/* 10.7.4.1 - interval between transmit opportunities
 	 * for applicant state machine
 	 */
+#if LOG_TIMERS
+	mrpd_log_printf("MRP start join timer\n");
+#endif
 	return mrpd_timer_start(mrp_db->join_timer, MRP_JOINTIMER_VAL);
 }
 
 int mrp_jointimer_stop(struct mrp_database *mrp_db)
 {
+#if LOG_TIMERS
+	mrpd_log_printf("MRP stop join timer\n");
+#endif
 	return mrpd_timer_stop(mrp_db->join_timer);
 }
 
@@ -243,11 +259,17 @@ int mrp_lvtimer_start(struct mrp_database *mrp_db)
 	 * controls how long the Registrar state machine stays in the
 	 * LV state before transitioning to the MT state.
 	 */
+#if LOG_TIMERS
+	mrpd_log_printf("MRP start leave timer\n");
+#endif
 	return mrpd_timer_start(mrp_db->lv_timer, MRP_LVTIMER_VAL);
 }
 
 int mrp_lvtimer_stop(struct mrp_database *mrp_db)
 {
+#if LOG_TIMERS
+	mrpd_log_printf("MRP stop leave timer\n");
+#endif
 	return mrpd_timer_stop(mrp_db->lv_timer);
 }
 
@@ -255,19 +277,25 @@ static unsigned long lva_next;
 
 int mrp_lvatimer_start(struct mrp_database *mrp_db)
 {
+	int timeout = 0;
 	/* leavealltimer has expired. (10.7.5.22)
 	 * on expire, sends a LEAVEALL message
 	 * value is RANDOM in range (LeaveAllTime , 1.5xLeaveAllTime)
 	 * timer is for all attributes of a given application and port, but
 	 * expires each listed attribute individually (per application)
 	 */
-	return mrpd_timer_start(mrp_db->lva_timer,
-				MRP_LVATIMER_VAL +
-				(random() % (MRP_LVATIMER_VAL / 2)));
+	timeout = MRP_LVATIMER_VAL + (random() % (MRP_LVATIMER_VAL / 2));
+#if LOG_TIMERS
+	mrpd_log_printf("MRP start leaveAll timer (%d ms)\n", timeout);
+#endif
+	return mrpd_timer_start(mrp_db->lva_timer, timeout);
 }
 
 int mrp_lvatimer_stop(struct mrp_database *mrp_db)
 {
+#if LOG_TIMERS
+	mrpd_log_printf("MRP stop leaveAll timer\n");
+#endif
 	return mrpd_timer_stop(mrp_db->lva_timer);
 }
 
@@ -307,6 +335,18 @@ int mrp_lvatimer_fsm(struct mrp_database *mrp_db, int event)
 		return -1;
 		break;
 	}
+#if LOG_MVRP || LOG_MSRP || LOG_MMRP
+	if (mrp_db->lva.state != la_state) {
+		mrpd_log_printf("mrp_lvatimer_fsm event %s state %s -> %s\n",
+				mrp_event_string(event),
+				mrp_lvatimer_state_string(mrp_db->lva.state),
+				mrp_lvatimer_state_string(la_state));
+	} else {
+		mrpd_log_printf("mrp_lvatimer_fsm event %s state %s\n",
+				mrp_event_string(event),
+				mrp_lvatimer_state_string(la_state));
+	}
+#endif
 	mrp_db->lva.state = la_state;
 	mrp_db->lva.sndmsg = sndmsg;
 	mrp_db->lva.tx = tx;
@@ -368,9 +408,6 @@ int mrp_applicant_fsm(struct mrp_database *mrp_db, mrp_applicant_attribute_t * a
 	int mrp_state = attrib->mrp_state;
 	int sndmsg = MRP_SND_NULL;
 
-#if LOG_MVRP || LOG_MSRP || LOG_MMRP
-	printf("APP FSM evt %s, state %s\n", mrp_event_string(event), mrp_state_string(mrp_state));
-#endif
 	switch (event) {
 	case MRP_EVENT_BEGIN:
 		mrp_state = MRP_VO_STATE;
@@ -718,10 +755,20 @@ int mrp_applicant_fsm(struct mrp_database *mrp_db, mrp_applicant_attribute_t * a
 		default:
 			break;
 		}
+	}
 #if LOG_MVRP || LOG_MSRP || LOG_MMRP
-		printf("APP FSM state transition to %s\n", mrp_state_string(mrp_state));
-#endif
+	if (attrib->mrp_state != mrp_state) {
+		mrpd_log_printf("mrp_applicant_fsm event %s, state %s -> %s\n",
+				mrp_event_string(event),
+				mrp_state_string(attrib->mrp_state),
+				mrp_state_string(mrp_state));
+	} else {
+		mrpd_log_printf("mrp_applicant_fsm event %s, state %s\n",
+				mrp_event_string(event),
+				mrp_state_string(mrp_state));
 	}
+#endif
+
 	attrib->mrp_state = mrp_state;
 	attrib->sndmsg = sndmsg;
 	attrib->encode = (optional ? MRP_ENCODE_OPTIONAL : MRP_ENCODE_YES);
@@ -788,7 +835,7 @@ mrp_registrar_fsm(mrp_registrar_attribute_t * attrib,
 			break;
 		case MRP_LV_STATE:
 			/* should stop leavetimer - but we have only 1 lvtimer
-			 * for all attributes, and recieving a LVTIMER event
+			 * for all attributes, and receiving a LVTIMER event
 			 * is a don't-care if the attribute is in the IN state.
 			 */
 			notify = MRP_NOTIFY_JOIN;
@@ -834,7 +881,19 @@ mrp_registrar_fsm(mrp_registrar_attribute_t * attrib,
 		return -1;
 		break;
 	}
-
+#if LOG_MVRP || LOG_MSRP || LOG_MMRP
+	if (attrib->mrp_state != mrp_state) {
+		mrpd_log_printf("mrp_registrar_fsm event %s, state %s -> %s\n",
+				mrp_event_string(event),
+				mrp_state_string(attrib->mrp_state),
+				mrp_state_string(mrp_state));
+
+	} else {
+		mrpd_log_printf("mrp_registrar_fsm event %s, state %s\n",
+				mrp_event_string(event),
+				mrp_state_string(mrp_state));
+	}
+#endif
 	attrib->mrp_state = mrp_state;
 	attrib->notify = notify;
 	return 0;
diff --git a/daemons/mrpd/mrp.h b/daemons/mrpd/mrp.h
index f0177c00..42e7e0e2 100644
--- a/daemons/mrpd/mrp.h
+++ b/daemons/mrpd/mrp.h
@@ -31,11 +31,15 @@
 
 ******************************************************************************/
 
-#define LOG_MRP 1
-#define LOG_MVRP 1
-#define LOG_MMRP 1
-#define LOG_MSRP 1
-
+/* control debug output on stdout */
+#define LOG_MRP 0
+#define LOG_MVRP 0
+#define LOG_MMRP 0
+#define LOG_MSRP 0
+#define LOG_TIMERS 0
+#define LOG_TXNOW 0
+#define LOG_CLIENT_RECV 0
+#define LOG_CLIENT_SEND 0
 
 #define MRP_ENCODE_YES		0	/* must send */
 #define MRP_ENCODE_OPTIONAL	1	/* send if smaller */
@@ -71,7 +75,7 @@ typedef struct mrp_registrar_attribute {
 #define MRP_VP_STATE	1	/* Very Anxious Passive */
 #define MRP_VN_STATE	2	/* Very Anxious New */
 #define MRP_AN_STATE	3	/* Anxious New */
-#define MRP_AA_STATE	4	/* Anxious New */
+#define MRP_AA_STATE	4	/* Anxious Active */
 #define MRP_QA_STATE	5	/* Quiet Active */
 #define MRP_LA_STATE	6	/* Leaving Active */
 #define MRP_AO_STATE	7	/* Anxious Observer State */
diff --git a/daemons/mrpd/mrpctl.c b/daemons/mrpd/mrpctl.c
index 888162ec..613eff75 100644
--- a/daemons/mrpd/mrpctl.c
+++ b/daemons/mrpd/mrpctl.c
@@ -322,11 +322,13 @@ main(int argc, char *argv[]) {
 	memset(msgbuf,0,1500);
 	sprintf(msgbuf,"V++:I=0002");
 	rc = send_control_msg(msgbuf, 1500 );
-	
+
+#ifdef YYYY	
 	memset(msgbuf,0,1500);
 	sprintf(msgbuf,"S+L:L=0050c24edb0a0001,D=2");
 	rc = send_control_msg(msgbuf, 1500);
-	
+#endif
+
 	do {
 		memset(msgbuf,0,1500);
 		sprintf(msgbuf,"M??");
diff --git a/daemons/mrpd/mrpd.c b/daemons/mrpd/mrpd.c
index 4096a952..158f667b 100644
--- a/daemons/mrpd/mrpd.c
+++ b/daemons/mrpd/mrpd.c
@@ -37,6 +37,7 @@
 #include <stdlib.h>
 #include <stdio.h>
 #include <stddef.h>
+#include <stdarg.h>
 #include <string.h>
 #include <syslog.h>
 #include <signal.h>
@@ -62,6 +63,8 @@
 #include "msrp.h"
 #include "mmrp.h"
 
+static void mrpd_log_timer_event(char *src, int event);
+
 /* global mgmt parameters */
 int daemonize;
 int mmrp_enable;
@@ -241,12 +244,13 @@ mrpd_send_ctl_msg(struct sockaddr_in *client_addr, char *notify_data,
 	if (-1 == control_socket)
 		return 0;
 
+#if LOG_CLIENT_SEND
 	if (logging_enable) {
-		printf("[%02d] CTL MSG:%s to CLNT %d\n", 
-		       gc_ctl_msg_count, notify_data, client_addr->sin_port);
+		mrpd_log_printf("[%02d] CLT MSG %05d:%s",
+		       gc_ctl_msg_count, client_addr->sin_port, notify_data);
 		gc_ctl_msg_count = (gc_ctl_msg_count + 1) % 100;
-	}		      
-
+	}
+#endif
 	rc = sendto(control_socket, notify_data, notify_len,
 		    0, (struct sockaddr *)client_addr, sizeof(struct sockaddr));
 	return rc;
@@ -308,8 +312,10 @@ int process_ctl_msg(char *buf, int buflen, struct sockaddr_in *client)
 
 	memset(respbuf, 0, sizeof(respbuf));
 
+#if LOG_CLIENT_RECV
 	if (logging_enable)
-		printf("CMD:%s from CLNT %d\n", buf, client->sin_port);
+		mrpd_log_printf("CMD:%s from CLNT %d\n", buf, client->sin_port);
+#endif
 
 	if (buflen < 3) {
 		printf("buflen = %d!\b", buflen);
@@ -658,14 +664,20 @@ void process_events(void)
 					(mmrp_socket, &sel_fds) mmrp_recv_msg();
 				if FD_ISSET
 					(MMRP_db->mrp_db.lva_timer, &sel_fds) {
+					mrpd_log_timer_event("MMRP",
+							     MRP_EVENT_LVATIMER);
 					mmrp_event(MRP_EVENT_LVATIMER, NULL);
 					}
 				if FD_ISSET
 					(MMRP_db->mrp_db.lv_timer, &sel_fds) {
+					mrpd_log_timer_event("MMRP",
+							     MRP_EVENT_LVTIMER);
 					mmrp_event(MRP_EVENT_LVTIMER, NULL);
 					}
 				if FD_ISSET
 					(MMRP_db->mrp_db.join_timer, &sel_fds) {
+					mrpd_log_timer_event("MMRP",
+							     MRP_EVENT_TX);
 					mmrp_event(MRP_EVENT_TX, NULL);
 					}
 			}
@@ -674,14 +686,20 @@ void process_events(void)
 					(mvrp_socket, &sel_fds) mvrp_recv_msg();
 				if FD_ISSET
 					(MVRP_db->mrp_db.lva_timer, &sel_fds) {
+					mrpd_log_timer_event("MVRP",
+							     MRP_EVENT_LVATIMER);
 					mvrp_event(MRP_EVENT_LVATIMER, NULL);
 					}
 				if FD_ISSET
 					(MVRP_db->mrp_db.lv_timer, &sel_fds) {
+					mrpd_log_timer_event("MVRP",
+							     MRP_EVENT_LVTIMER);
 					mvrp_event(MRP_EVENT_LVTIMER, NULL);
 					}
 				if FD_ISSET
 					(MVRP_db->mrp_db.join_timer, &sel_fds) {
+					mrpd_log_timer_event("MVRP",
+							     MRP_EVENT_TX);
 					mvrp_event(MRP_EVENT_TX, NULL);
 					}
 			}
@@ -690,14 +708,20 @@ void process_events(void)
 					(msrp_socket, &sel_fds) msrp_recv_msg();
 				if FD_ISSET
 					(MSRP_db->mrp_db.lva_timer, &sel_fds) {
+					mrpd_log_timer_event("MSRP",
+							     MRP_EVENT_LVATIMER);
 					msrp_event(MRP_EVENT_LVATIMER, NULL);
 					}
 				if FD_ISSET
 					(MSRP_db->mrp_db.lv_timer, &sel_fds) {
+					mrpd_log_timer_event("MSRP",
+							     MRP_EVENT_LVTIMER);
 					msrp_event(MRP_EVENT_LVTIMER, NULL);
 					}
 				if FD_ISSET
 					(MSRP_db->mrp_db.join_timer, &sel_fds) {
+					mrpd_log_timer_event("MSRP",
+							     MRP_EVENT_TX);
 					msrp_event(MRP_EVENT_TX, NULL);
 					}
 			}
@@ -719,16 +743,28 @@ void process_events(void)
 			if (FD_ISSET(txnowevt_fd, &sel_fds)) {
 				uint64_t count;
 				read(txnowevt_fd, &count, sizeof(count));
-				if (mmrp_enable && MMRP_db->mrp_db.schedule_tx_flag) {
+				if (mmrp_enable
+				    && MMRP_db->mrp_db.schedule_tx_flag) {
 					MMRP_db->mrp_db.schedule_tx_flag = 0;
+#if LOG_TXNOW
+					mrpd_log_printf("MMRP txnow event\n");
+#endif
 					mmrp_event(MRP_EVENT_TX, NULL);
 				}
-				if (mvrp_enable && MVRP_db->mrp_db.schedule_tx_flag) {
+				if (mvrp_enable
+				    && MVRP_db->mrp_db.schedule_tx_flag) {
 					MVRP_db->mrp_db.schedule_tx_flag = 0;
+#if LOG_TXNOW
+					mrpd_log_printf("MVRP txnow event\n");
+#endif
 					mvrp_event(MRP_EVENT_TX, NULL);
 				}
-				if (msrp_enable && MSRP_db->mrp_db.schedule_tx_flag) {
+				if (msrp_enable
+				    && MSRP_db->mrp_db.schedule_tx_flag) {
 					MSRP_db->mrp_db.schedule_tx_flag = 0;
+#if LOG_TXNOW
+					mrpd_log_printf("MSRP txnow event\n");
+#endif
 					msrp_event(MRP_EVENT_TX, NULL);
 				}
 			}
@@ -865,3 +901,34 @@ int main(int argc, char *argv[])
 	return rc;
 
 }
+
+static void mrpd_log_timer_event(char *src, int event)
+{
+#if LOG_TIMERS
+	if (event == MRP_EVENT_LVATIMER) {
+		mrpd_log_printf("%s leaveAll timer expires ->\n", src);
+	} else if (event == MRP_EVENT_LVTIMER) {
+		mrpd_log_printf("%s leave timer expires ->\n", src);
+	} else if (event == MRP_EVENT_TX) {
+		mrpd_log_printf("%s join timer expires ->\n", src);
+	}
+#endif
+}
+
+void mrpd_log_printf(const char *fmt, ...)
+{
+	struct timeval tv;
+	char sz[512];
+
+	if (logging_enable) {
+		gettimeofday(&tv, NULL);
+		va_list arglist;
+		va_start(arglist, fmt);
+		vsnprintf(sz, 512, fmt, arglist);
+		printf("MRPD %03d.%06d %s",
+			(int)(tv.tv_sec % 1000),
+			(int)tv.tv_usec,
+			sz);
+		va_end(arglist);
+	}
+}
diff --git a/daemons/mrpd/mrpd.h b/daemons/mrpd/mrpd.h
index 19d315e6..a7b593e2 100644
--- a/daemons/mrpd/mrpd.h
+++ b/daemons/mrpd/mrpd.h
@@ -130,3 +130,5 @@ int mrpd_init_protocol_socket(uint16_t etype, SOCKET * sock,
 			      unsigned char *multicast_addr);
 int mrpd_close_socket(SOCKET sock);
 int mrpd_recvmsgbuf(SOCKET sock, char **buf);
+
+void mrpd_log_printf(const char *fmt, ...);
diff --git a/daemons/mrpd/mrpw.c b/daemons/mrpd/mrpw.c
index 182ee7d2..e6e5234e 100644
--- a/daemons/mrpd/mrpw.c
+++ b/daemons/mrpd/mrpw.c
@@ -726,10 +726,10 @@ int mrpd_reclaim()
 void mrp_schedule_tx_event(void)
 {
 	if (!SetEvent(pkt_events[tx_request_event]))
-		printf("SetEvent tx_request_event failed (%d)\n", GetLastError());
+		printf("SetEvent tx_request_event failed (%d)\n",
+		       GetLastError());
 }
 
-
 HANDLE kill_packet_capture;
 
 void process_events(void)
diff --git a/daemons/mrpd/msrp.c b/daemons/mrpd/msrp.c
index 948a151b..136b153d 100644
--- a/daemons/mrpd/msrp.c
+++ b/daemons/mrpd/msrp.c
@@ -255,7 +255,7 @@ int msrp_event(int event, struct msrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MSRP
-			printf("MSRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MSRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MSRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TXLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -274,7 +274,7 @@ int msrp_event(int event, struct msrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MSRP
-			printf("MSRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MSRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MSRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_RLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -291,7 +291,7 @@ int msrp_event(int event, struct msrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MSRP
-			printf("MSRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MSRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MSRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TX);
 			attrib = attrib->next;
@@ -318,7 +318,7 @@ int msrp_event(int event, struct msrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MSRP
-			printf("MSRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MSRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MSRP_db->mrp_db), &(attrib->applicant),
 					  MRP_EVENT_PERIODIC);
@@ -2171,8 +2171,6 @@ msrp_emit_listenvectors(unsigned char *msgbuf, unsigned char *msgbuf_eof,
 
 		listen_declare_end = listen_declare_idx;
 
-		printf("######listen_declare_end %d\n", listen_declare_end);
-
 		for (listen_declare_idx = 0;
 		     listen_declare_idx < ((listen_declare_end / 4) * 4);
 		     listen_declare_idx += 4) {
@@ -2351,6 +2349,9 @@ int msrp_txpdu(void)
 	msgbuf_len = mrpdu_msg_ptr - msgbuf;
 
 	bytes = mrpd_send(msrp_socket, msgbuf, msgbuf_len, 0);
+#if LOG_MSRP
+	mrpd_log_printf("MSRP send PDU\n");
+#endif
 	if (bytes <= 0)
 		goto out;
 
@@ -2825,7 +2826,7 @@ static int msrp_cmd_report_domain_status(struct msrpdu_domain *domain, int repor
 int msrp_recv_cmd(char *buf, int buflen, struct sockaddr_in *client)
 {
 	int rc;
-	char respbuf[8];
+	char respbuf[12];
 	int mrp_event;
 	unsigned int substate;
 	struct msrpdu_domain domain_param;
@@ -2833,7 +2834,7 @@ int msrp_recv_cmd(char *buf, int buflen, struct sockaddr_in *client)
 	int err_index;
 
 	if (NULL == MSRP_db) {
-		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s", buf);
+		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s\n", buf);
 		mrpd_send_ctl_msg(client, respbuf, sizeof(respbuf));
 		goto out;
 	}
diff --git a/daemons/mrpd/mvrp.c b/daemons/mrpd/mvrp.c
index 0a3ec0f1..92a41ca0 100644
--- a/daemons/mrpd/mvrp.c
+++ b/daemons/mrpd/mvrp.c
@@ -151,7 +151,7 @@ int mvrp_event(int event, struct mvrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MVRP
-			printf("MVRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MVRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MVRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TXLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -170,7 +170,7 @@ int mvrp_event(int event, struct mvrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MVRP
-			printf("MVRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MVRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MVRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_RLA);
 			mrp_registrar_fsm(&(attrib->registrar),
@@ -187,7 +187,7 @@ int mvrp_event(int event, struct mvrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MVRP
-			printf("MVRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MVRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MVRP_db->mrp_db), &(attrib->applicant), MRP_EVENT_TX);
 			attrib = attrib->next;
@@ -214,7 +214,7 @@ int mvrp_event(int event, struct mvrp_attribute *rattrib)
 
 		while (NULL != attrib) {
 #if LOG_MVRP
-			printf("MVRP -> mrp_applicant_fsm\n");
+			mrpd_log_printf("MVRP -> mrp_applicant_fsm\n");
 #endif
 			mrp_applicant_fsm(&(MVRP_db->mrp_db), &(attrib->applicant),
 					  MRP_EVENT_PERIODIC);
@@ -246,7 +246,7 @@ int mvrp_event(int event, struct mvrp_attribute *rattrib)
 		}
 
 #if LOG_MVRP
-		printf("MVRP -> mrp_applicant_fsm\n");
+		mrpd_log_printf("MVRP -> mrp_applicant_fsm\n");
 #endif
 		mrp_applicant_fsm(&(MVRP_db->mrp_db), &(attrib->applicant), event);
 		/* remap local requests into registrar events */
@@ -878,6 +878,9 @@ int mvrp_txpdu(void)
 	msgbuf_len = mrpdu_msg_ptr - msgbuf;
 
 	bytes = mrpd_send(mvrp_socket, msgbuf, msgbuf_len, 0);
+#if LOG_MVRP
+	mrpd_log_printf("MVRP send PDU\n");
+#endif
 	if (bytes <= 0)
 		goto out;
 
@@ -1069,12 +1072,12 @@ int mvrp_recv_cmd(char *buf, int buflen, struct sockaddr_in *client)
 {
 	int rc;
 	int mrp_event;
-	char respbuf[8];
+	char respbuf[12];
 	uint16_t vid_param;
 	int err_index;
 
 	if (NULL == MVRP_db) {
-		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s", buf);
+		snprintf(respbuf, sizeof(respbuf) - 1, "ERC %s\n", buf);
 		mrpd_send_ctl_msg(client, respbuf, sizeof(respbuf));
 		goto out;
 	}