Mercurial > hg > freeDiameter

changeset 688:8c3dc8584dab

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Prepared capability for messages logging to separate files / folders
author Sebastien Decugis <sdecugis@nict.go.jp>
date Wed, 19 Jan 2011 19:05:30 +0900
parents 026802543f57
children 933d098fc75d
files doc/dbg_interactive.py.sample extensions/app_radgw/rgwx_acct.c extensions/dbg_interactive/messages.i include/freeDiameter/libfdproto.h libfdcore/core.c libfdcore/messages.c libfdcore/p_ce.c libfdcore/p_out.c libfdcore/p_psm.c libfdcore/p_sr.c libfdcore/peers.c libfdcore/queues.c libfdcore/routing_dispatch.c libfdcore/server.c libfdproto/messages.c tests/testcnx.c
diffstat 16 files changed, 90 insertions(+), 73 deletions(-) [+]
line wrap: on
line diff
--- a/doc/dbg_interactive.py.sample	Wed Jan 19 17:08:21 2011 +0900
+++ b/doc/dbg_interactive.py.sample	Wed Jan 19 19:05:30 2011 +0900
@@ -363,6 +363,7 @@
 # Create empt (as for avps, pass None or a dictionary object as 1st param, and flags as optional 2nd param)y
 a_msg = msg()
 a_msg.dump()
+a_msg.log(FD_MSG_LOG_DROPPED, "Check libfdproto for more details. Configure with fd_msg_log_config.")
 del a_msg
 
 # It is also possible to pass MSGFL_* flags in second parameter (ALLOC_ETEID is default)
--- a/extensions/app_radgw/rgwx_acct.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/extensions/app_radgw/rgwx_acct.c	Wed Jan 19 19:05:30 2011 +0900
@@ -1214,7 +1214,7 @@
 		
 out:
 	if (answer && *answer) {
-		TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding...");
+		TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding anyway...");
 		fd_msg_dump_walk( INFO, *answer );
 		fd_msg_free(*answer);
 		*answer = NULL;
--- a/extensions/dbg_interactive/messages.i	Wed Jan 19 17:08:21 2011 +0900
+++ b/extensions/dbg_interactive/messages.i	Wed Jan 19 19:05:30 2011 +0900
@@ -253,6 +253,11 @@
 			fd_msg_dump_one(0, $self);
 	}
 	
+	/* Log to file (depending on config)  */
+	void log ( enum fd_msg_log_cause cause, char * message ) {
+		fd_msg_log( cause, $self, message );
+	}
+	
 	/* Model */
 	struct dict_object * model() {
 		struct dict_object * m = NULL;
--- a/include/freeDiameter/libfdproto.h	Wed Jan 19 17:08:21 2011 +0900
+++ b/include/freeDiameter/libfdproto.h	Wed Jan 19 19:05:30 2011 +0900
@@ -2054,9 +2054,10 @@
 enum fd_msg_log_cause {
 	FD_MSG_LOG_DROPPED = 0,  /* message has been dropped by the framework */ 
 	FD_MSG_LOG_RECEIVED,     /* message received from the network */ 
-	FD_MSG_LOG_SENT          /* message sent to another peer */ 
+	FD_MSG_LOG_SENT,         /* message sent to another peer */ 
+	FD_MSG_LOG_NODELIVER     /* message could not be delivered to any peer */ 
 };
-#define FD_MSG_LOG_MAX FD_MSG_LOG_SENT
+#define FD_MSG_LOG_MAX FD_MSG_LOG_NODELIVER
 void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... );
 
 /* configure the msg_log facility */
@@ -2066,6 +2067,7 @@
 	FD_MSG_LOGTO_DIR    /* Messages are dumped in different files within one directory defined in arg. */
 };
 int fd_msg_log_config(enum fd_msg_log_cause cause, enum fd_msg_log_method method, const char * arg);
+void ml_conf_init(struct dictionary *dict);
 
 /*********************************************/
 /*   Message metadata management functions   */
--- a/libfdcore/core.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/core.c	Wed Jan 19 19:05:30 2011 +0900
@@ -194,6 +194,9 @@
 	memset(&g_conf, 0, sizeof(struct fd_config));
 	fd_g_config = &g_conf;
 	CHECK_FCT( fd_conf_init() );
+	
+	/* Initialize the message logging facility */
+	ml_conf_init(fd_g_config->cnf_dict);
 
 	/* Add definitions of the base protocol */
 	CHECK_FCT( fd_dict_base_protocol(fd_g_config->cnf_dict) );
--- a/libfdcore/messages.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/messages.c	Wed Jan 19 19:05:30 2011 +0900
@@ -312,8 +312,8 @@
 		&& (ret != ENOTSUP))	/* Command is not supported / Mandatory AVP is not supported */
 		return ret;
 	
-	fd_log_debug("The following message does not comply to the dictionary and/or rules (%s):\n", pei.pei_errcode);
-	fd_msg_dump_walk(NONE, m);
+	TRACE_DEBUG(INFO, "A message does not comply to the dictionary and/or rules (%s)", pei.pei_errcode);
+	fd_msg_dump_walk(FULL, m);
 	
 	CHECK_FCT( fd_msg_hdr(m, &hdr) );
 	
@@ -363,6 +363,7 @@
 		} while (0);
 		
 		/* Just discard */
+		fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
 		CHECK_FCT( fd_msg_free( m ) );
 		*msg = NULL;
 	}
--- a/libfdcore/p_ce.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/p_ce.c	Wed Jan 19 19:05:30 2011 +0900
@@ -597,6 +597,7 @@
 destroy:
 	fd_cnx_destroy(recv_cnx);
 	if (*cer) {
+		fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
 		fd_msg_free(*cer);
 		*cer = NULL;
 	}
@@ -664,8 +665,7 @@
 	fd_cpu_flush_cache();
 	if (req || (peer->p_hdr.info.runtime.pir_state != STATE_WAITCEA)) {
 		if (*msg) {
-			fd_log_debug("Received CER/CEA message while in state '%s', discarded.\n", STATE_STR(peer->p_hdr.info.runtime.pir_state));
-			fd_msg_dump_walk(NONE, *msg);
+			fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.\n", STATE_STR(peer->p_hdr.info.runtime.pir_state));
 			CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
 			*msg = NULL;
 		}
@@ -910,6 +910,7 @@
 	
 cleanup:
 	if (msg) {
+		fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
 		fd_msg_free(msg);
 	}
 	fd_p_ce_clear_cnx(peer, NULL);
--- a/libfdcore/p_out.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/p_out.c	Wed Jan 19 19:05:30 2011 +0900
@@ -59,17 +59,13 @@
 		*hbh = hdr->msg_hbhid + 1;
 	}
 	
-	/* Log the message */
-	if (TRACE_BOOL(FULL)) {
-		CHECK_FCT_DO(  fd_msg_update_length(*msg), /* continue */  );
-		TRACE_DEBUG(FULL, "Sending the following message on connection '%s':", fd_cnx_getid(cnx));
-		fd_msg_dump_walk(FULL, *msg);
-	}
-	
 	/* Create the message buffer */
 	CHECK_FCT(fd_msg_bufferize( *msg, &buf, &sz ));
 	pthread_cleanup_push( free, buf );
 	
+	/* Log the message */
+	fd_msg_log( FD_MSG_LOG_SENT, *msg, "Sent to '%s'", fd_cnx_getid(cnx));
+	
 	/* Save a request before sending so that there is no race condition with the answer */
 	if (msg_is_a_req) {
 		CHECK_FCT_DO( ret = fd_p_sr_store(srl, msg, &hdr->msg_hbhid, bkp_hbh), { free(buf); return ret; } );
@@ -92,7 +88,10 @@
 {
 	struct msg *msg = arg;
 	CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &msg),
-			CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */));
+		{
+			fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
+			CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */);
+		} );
 }
 
 /* The code of the "out" thread */
@@ -111,6 +110,7 @@
 	/* Loop until cancelation */
 	while (1) {
 		struct msg * msg;
+		int ret;
 		
 		/* Retrieve next message to send */
 		CHECK_FCT_DO( fd_fifo_get(peer->p_tosend, &msg), goto error );
@@ -119,11 +119,10 @@
 		pthread_cleanup_push(cleanup_requeue, msg);
 		
 		/* Send the message, log any error */
-		CHECK_FCT_DO( do_send(&msg, 0, peer->p_cnxctx, &peer->p_hbh, &peer->p_sr),
+		CHECK_FCT_DO( ret = do_send(&msg, 0, peer->p_cnxctx, &peer->p_hbh, &peer->p_sr),
 			{
 				if (msg) {
-					fd_log_debug("An error occurred while sending this message, it was lost:\n");
-					fd_msg_dump_walk(NONE, msg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
 					fd_msg_free(msg);
 				}
 			} );
@@ -150,6 +149,7 @@
 		CHECK_FCT( fd_fifo_post(peer->p_tosend, msg) );
 		
 	} else {
+		int ret;
 		uint32_t *hbh = NULL;
 		
 		/* In other cases, the thread is not running, so we handle the sending directly */
@@ -160,11 +160,10 @@
 			cnx = peer->p_cnxctx;
 
 		/* Do send the message */
-		CHECK_FCT_DO( do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
+		CHECK_FCT_DO( ret = do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
 			{
 				if (msg) {
-					fd_log_debug("An error occurred while sending this message, it was lost:\n");
-					fd_msg_dump_walk(NONE, *msg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
 					fd_msg_free(*msg);
 					*msg = NULL;
 				}
--- a/libfdcore/p_psm.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/p_psm.c	Wed Jan 19 19:05:30 2011 +0900
@@ -165,6 +165,7 @@
 			
 			case FDEVP_CNX_INCOMING: {
 				struct cnx_incoming * evd = ev->data;
+				fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
 				CHECK_FCT_DO( fd_msg_free(evd->cer), /* continue */);
 				fd_cnx_destroy(evd->cnx);
 			}
@@ -393,13 +394,8 @@
 				goto psm_loop;
 			} );
 		
-		TRACE_DEBUG(FULL, "Received a message (%zdb) from '%s'", ev_sz, peer->p_hdr.info.pi_diamid);
-		if (TRACE_BOOL(FULL+1)) {
-			CHECK_FCT_DO( fd_msg_parse_dict( msg, fd_g_config->cnf_dict, NULL ), );
-			fd_msg_dump_walk(FULL, msg);
-		} else {
-			fd_msg_dump_one(FULL, msg);
-		}
+		/* Log incoming message */
+		fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from '%s'", ev_sz, peer->p_hdr.info.pi_diamid );
 	
 		/* Extract the header */
 		CHECK_FCT_DO( fd_msg_hdr(msg, &hdr), goto psm_end );
@@ -410,8 +406,7 @@
 			/* Search matching request (same hbhid) */
 			CHECK_FCT_DO( fd_p_sr_fetch(&peer->p_sr, hdr->msg_hbhid, &req), goto psm_end );
 			if (req == NULL) {
-				fd_log_debug("Received a Diameter answer message with no corresponding sent request, discarding.\n");
-				fd_msg_dump_walk(NONE, msg);
+				fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
 				fd_msg_free(msg);
 				goto psm_loop;
 			}
@@ -452,8 +447,7 @@
 				case STATE_CLOSED:
 				default:
 					/* In such case, just discard the message */
-					fd_log_debug("Received a routable message while not in OPEN state from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
-					fd_msg_dump_walk(NONE, msg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received from peer '%s' while connection was not in OPEN state.", peer->p_hdr.info.pi_diamid );
 					fd_msg_free(msg);
 			}
 			goto psm_loop;
@@ -467,8 +461,10 @@
 			} else {
 				if (msg) {
 					/* Send the error back to the peer */
-					CHECK_FCT_DO( fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED), /* In case of error the message has already been dumped */ );
+					CHECK_FCT_DO( ret = fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED),  );
 					if (msg) {
+						/* Only if an error occurred & the message was not saved / dumped */
+						fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
 						CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
 					}
 				} else {
@@ -497,8 +493,7 @@
 			
 			default:
 				/* Unknown / unexpected / invalid message */
-				fd_log_debug("Received an unknown local message from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
-				fd_msg_dump_walk(NONE, msg);
+				TRACE_DEBUG(INFO, "Invalid non-routable command received: %u.", hdr->msg_code);
 				if (hdr->msg_flags & CMD_FLAG_REQUEST) {
 					do {
 						/* Reply with an error code */
@@ -517,6 +512,7 @@
 				
 				/* Cleanup the message if not done */
 				if (msg) {
+					fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
 					CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
 					msg = NULL;
 				}
@@ -524,8 +520,7 @@
 		
 		/* At this point the message must have been fully handled already */
 		if (msg) {
-			fd_log_debug("Internal error: unhandled message (discarded)!\n");
-			fd_msg_dump_walk(NONE, msg);
+			fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: unhandled message.", peer->p_hdr.info.pi_diamid );
 			fd_msg_free(msg);
 		}
 		
@@ -601,6 +596,7 @@
 			params->cnx = NULL;
 		}
 		if (params->cer) {
+			fd_msg_log( FD_MSG_LOG_DROPPED, params->cer, "Internal error: this CER was not handled as expected." );
 			CHECK_FCT_DO( fd_msg_free(params->cer), );
 			params->cer = NULL;
 		}
--- a/libfdcore/p_sr.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/p_sr.c	Wed Jan 19 19:05:30 2011 +0900
@@ -108,6 +108,7 @@
 	
 	/* If the callback did not dispose of the message, do it now */
 	if (expired_req) {
+		fd_msg_log(FD_MSG_LOG_DROPPED, expired_req, "Expiration period completed without an answer, and the expiry callback did not dispose of the message.");
 		CHECK_FCT_DO( fd_msg_free(expired_req), /* ignore */ );
 	}
 	
@@ -295,6 +296,7 @@
 		fd_list_unlink(&sr->expire);
 		if (fd_msg_is_routable(sr->req)) {
 			struct msg_hdr * hdr = NULL;
+			int ret;
 			
 			/* Set the 'T' flag */
 			CHECK_FCT_DO(fd_msg_hdr(sr->req, &hdr), /* continue */);
@@ -302,10 +304,14 @@
 				hdr->msg_flags |= CMD_FLAG_RETRANSMIT;
 			
 			/* Requeue for sending to another peer */
-			CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &sr->req),
-					CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */));
+			CHECK_FCT_DO( ret = fd_fifo_post(fd_g_outgoing, &sr->req),
+				{
+					fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
+					CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */)
+				});
 		} else {
-			/* Just free the request... */
+			/* Just free the request. */
+			fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Local message discarded during failover" );
 			CHECK_FCT_DO(fd_msg_free(sr->req), /* Ignore */);
 		}
 		free(sr);
--- a/libfdcore/peers.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/peers.c	Wed Jan 19 19:05:30 2011 +0900
@@ -210,8 +210,11 @@
 	/* Requeue all messages in the "out" queue */
 	while ( fd_fifo_tryget(peer->p_tosend, &m) == 0 ) {
 		CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &m), 
+			{
 				/* fallback: destroy the message */
-				CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */));
+				fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
+				CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */)
+			} );
 	}
 	
 	/* Requeue all routable sent requests */
--- a/libfdcore/queues.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/queues.c	Wed Jan 19 19:05:30 2011 +0900
@@ -73,8 +73,7 @@
 		CHECK_FCT(ret);
 		
 		/* We got one! */
-		fd_log_debug("The following message is lost because the daemon is stopping:\n");
-		fd_msg_dump_walk(NONE, msg);
+		fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
 		fd_msg_free(msg);
 	}
 	
--- a/libfdcore/routing_dispatch.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/routing_dispatch.c	Wed Jan 19 19:05:30 2011 +0900
@@ -408,8 +408,7 @@
 			CHECK_FCT( fd_peer_getbyid( id, (void *)&peer ) );
 
 			if (!peer) {
-				TRACE_DEBUG(INFO, "Unable to send error '%s' to deleted peer '%s' in reply to:", error_code, id);
-				fd_msg_dump_walk(INFO, *pmsg);
+				fd_msg_log(FD_MSG_LOG_DROPPED, *pmsg, "Unable to send error '%s' to deleted peer '%s' in reply to this message.", error_code, id);
 				fd_msg_free(*pmsg);
 				*pmsg = NULL;
 				return 0;
@@ -466,8 +465,7 @@
 				CHECK_FCT( fd_fifo_post(fd_g_outgoing, pmsg) );
 			}
 			if (*pmsg) {	/* another error happen'd */
-				TRACE_DEBUG(INFO, "An unexpected error occurred (%s), discarding a message:", strerror(ret));
-				fd_msg_dump_walk(INFO, *pmsg);
+				fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
 				CHECK_FCT_DO( fd_msg_free(*pmsg), /* continue */);
 				*pmsg = NULL;
 			}
@@ -521,8 +519,7 @@
 				}
 				
 				if (!is_req) {
-					TRACE_DEBUG(INFO, "Received an answer to a localy issued query, but no handler processed this answer!");
-					fd_msg_dump_walk(INFO, *pmsg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
 					fd_msg_free(*pmsg);
 					*pmsg = NULL;
 					break;
@@ -747,6 +744,7 @@
 		/* requests: dir = 1 & 2 => in order; answers = 3 & 2 => in reverse order */
 		for (	li = (is_req ? rt_fwd_list.next : rt_fwd_list.prev) ; *pmsg && (li != &rt_fwd_list) ; li = (is_req ? li->next : li->prev) ) {
 			struct rt_hdl * rh = (struct rt_hdl *)li;
+			int ret;
 
 			if (is_req && (rh->dir > RT_FWD_ALL))
 				break;
@@ -755,10 +753,9 @@
 
 			/* Ok, call this cb */
 			TRACE_DEBUG(ANNOYING, "Calling next FWD callback on %p : %p", *pmsg, rh->rt_fwd_cb);
-			CHECK_FCT_DO( (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
+			CHECK_FCT_DO( ret = (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
 				{
-					TRACE_DEBUG(INFO, "A FWD routing callback returned an error, message discarded.");
-					fd_msg_dump_walk(INFO, *pmsg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
 					fd_msg_free(*pmsg);
 					*pmsg = NULL;
 				} );
@@ -816,8 +813,7 @@
 		CHECK_FCT( fd_peer_getbyid( qry_src, (void *) &peer ) );
 		fd_cpu_flush_cache();
 		if ((!peer) || (peer->p_hdr.info.runtime.pir_state != STATE_OPEN)) {
-			TRACE_DEBUG(INFO, "Unable to forward answer message to peer '%s', deleted or not in OPEN state.", qry_src);
-			fd_msg_dump_walk(INFO, *pmsg);
+			fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
 			fd_msg_free(*pmsg);
 			*pmsg = NULL;
 			return 0;
@@ -896,8 +892,7 @@
 			TRACE_DEBUG(ANNOYING, "Calling next OUT callback on %p : %p (prio %d)", *pmsg, rh->rt_out_cb, rh->prio);
 			CHECK_FCT_DO( ret = (*rh->rt_out_cb)(rh->cbdata, *pmsg, candidates),
 				{
-					TRACE_DEBUG(INFO, "An OUT routing callback returned an error (%s) ! Message discarded.", strerror(ret));
-					fd_msg_dump_walk(INFO, *pmsg);
+					fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
 					fd_msg_free(*pmsg);
 					*pmsg = NULL;
 					break;
@@ -946,8 +941,7 @@
 
 	/* If the message has not been sent, return an error */
 	if (*pmsg) {
-		TRACE_DEBUG(INFO, "Could not send the following message, replying with UNABLE_TO_DELIVER");
-		fd_msg_dump_walk(INFO, *pmsg);
+		fd_msg_log( FD_MSG_LOG_NODELIVER, *pmsg, "No suitable candidate to route the message to." );
 		return_error( pmsg, "DIAMETER_UNABLE_TO_DELIVER", "No suitable candidate to route the message to", NULL);
 	}
 
--- a/libfdcore/server.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdcore/server.c	Wed Jan 19 19:05:30 2011 +0900
@@ -142,8 +142,6 @@
 	/* We expect a CER, it must parse with our dictionary and rules */
 	CHECK_FCT_DO( fd_msg_parse_rules( msg, fd_g_config->cnf_dict, NULL ), /* Parsing failed -- trace details ? */ goto cleanup );
 	
-	fd_msg_dump_walk(FULL, msg);
-	
 	/* Now check we received a CER */
 	CHECK_FCT_DO( fd_msg_hdr ( msg, &hdr ), goto fatal_error );
 	CHECK_PARAMS_DO( (hdr->msg_appl == 0) && (hdr->msg_flags & CMD_FLAG_REQUEST) && (hdr->msg_code == CC_CAPABILITIES_EXCHANGE),
@@ -163,6 +161,12 @@
 	fd_list_unlink( &c->chain );
 	CHECK_POSIX_DO( pthread_mutex_unlock(&s->clients_mtx), goto fatal_error );
 	
+	/* Cleanup the parsed message if any */
+	if (msg) {
+		fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received invalid/unexpected message from connecting client '%s'", fd_cnx_getid(c->conn) );
+		CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
+	}
+	
 	/* Destroy the connection object if present */
 	if (c->conn)
 		fd_cnx_destroy(c->conn);
@@ -170,11 +174,6 @@
 	/* Cleanup the received buffer if any */
 	free(buf);
 	
-	/* Cleanup the parsed message if any */
-	if (msg) {
-		CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
-	}
-	
 	/* Detach the thread, cleanup the client structure */
 	pthread_detach(pthread_self());
 	free(c);
--- a/libfdproto/messages.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/libfdproto/messages.c	Wed Jan 19 19:05:30 2011 +0900
@@ -792,7 +792,7 @@
 }
 
 /* Dump a message to a specified file stream */
-static void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
+void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
 {
 	msg_or_avp * ref = msg;
 	int indent = 2;
@@ -2262,8 +2262,7 @@
 				*error_code = "DIAMETER_APPLICATION_UNSUPPORTED";
 			*action = DISP_ACT_ERROR;
 		} else {
-			TRACE_DEBUG(INFO, "Received an answer to a local query with an unsupported application %d, discarding...",  (*msg)->msg_public.msg_appl);
-			fd_msg_dump_walk(INFO, *msg);
+			fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Received this answer to a local query with an unsupported application %d", (*msg)->msg_public.msg_appl);
 			fd_msg_free(*msg);
 			*msg = NULL;
 		}
@@ -2336,12 +2335,14 @@
 	} causes[FD_MSG_LOG_MAX + 1];
 	pthread_mutex_t lock;
 	int		init;
+	struct dictionary *dict;	
 } ml_conf = { .lock = PTHREAD_MUTEX_INITIALIZER, .init = 0 };
 
-static void ml_conf_init(void) 
+void ml_conf_init(struct dictionary *dict) 
 {
 	memset(&ml_conf.causes, 0, sizeof(ml_conf.causes));
 	ml_conf.init = 1;
+	ml_conf.dict = dict;
 }
 
 /* Set a configuration property */
@@ -2356,7 +2357,7 @@
 	/* Lock the configuration */
 	CHECK_POSIX( pthread_mutex_lock(&ml_conf.lock) );
 	if (!ml_conf.init) {
-		ml_conf_init();
+		ASSERT(0);
 	}
 	
 	/* Now set the parameter */
@@ -2405,7 +2406,7 @@
 	/* First retrieve the config for this message */
 	CHECK_POSIX_DO( pthread_mutex_lock(&ml_conf.lock), );
 	if (!ml_conf.init) {
-		ml_conf_init();
+		ASSERT(0);
 	}
 	meth    = ml_conf.causes[cause].meth;
 	metharg = ml_conf.causes[cause].metharg;
@@ -2419,13 +2420,20 @@
 			
 		case FD_MSG_LOGTO_FILE:
 			TODO("Log to arg file");
+			TODO("Log a note to debug stream");
 			break;
 		case FD_MSG_LOGTO_DIR:
 			TODO("Log to arg directory in a new file");
+			TODO("Log a note to debug stream");
 			break;
 	}
 	
-	/* Then dump the prefix message to this stream */
+	/* For file methods, let's parse the message so it looks better */
+	if ((meth != FD_MSG_LOGTO_DEBUGONLY) && ml_conf.dict) {
+		CHECK_FCT_DO( fd_msg_parse_dict( msg, ml_conf.dict, NULL ), );
+	}
+	
+	/* Then dump the prefix message to this stream, & to debug stream */
 	(void)pthread_mutex_lock(&fd_log_lock);
 	pthread_cleanup_push(fd_cleanup_mutex_silent, &fd_log_lock);
 	va_start(ap, prefix_format);
--- a/tests/testcnx.c	Wed Jan 19 17:08:21 2011 +0900
+++ b/tests/testcnx.c	Wed Jan 19 19:05:30 2011 +0900
@@ -641,7 +641,7 @@
 		/* Add the AVP */
 		CHECK( 0, fd_msg_avp_add( cer, MSG_BRW_LAST_CHILD, oh) );
 
-		#if 1
+		#if 0
 		/* For debug: dump the object */
 		fd_log_debug("Dumping CER\n");
 		fd_msg_dump_walk(0, cer);
"Welcome to our mercurial repository"