--- a/extensions/CMakeLists.txt	Fri May 10 13:24:23 2013 +0200
+++ b/extensions/CMakeLists.txt	Fri May 10 13:26:03 2013 +0200
@@ -85,6 +85,7 @@
 # Debug & test extensions
 
 FD_EXTENSION_SUBDIR(dbg_monitor "Outputs periodical status information"              OFF)
+FD_EXTENSION_SUBDIR(dbg_msg_timings "Show some timing information for messages"      OFF)
 FD_EXTENSION_SUBDIR(dbg_rt      "Routing extension for debugging the routing module" OFF)
 FD_EXTENSION_SUBDIR(test_app    "Testing application to send dummy message to another peer, like a Diameter 'ping'" OFF)
 FD_EXTENSION_SUBDIR(test_sip    "Testing application to simulate Diameter-SIP client (RFC4740)" OFF)

--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/extensions/dbg_msg_timings/CMakeLists.txt	Fri May 10 13:26:03 2013 +0200
@@ -0,0 +1,12 @@
+# Messages timing extension
+PROJECT("Messages timing extension" C)
+FD_ADD_EXTENSION(dbg_msg_timings dbg_msg_timings.c)
+
+
+####
+## INSTALL section ##
+
+INSTALL(TARGETS dbg_msg_timings
+	LIBRARY DESTINATION ${INSTALL_EXTENSIONS_SUFFIX}
+	COMPONENT freeDiameter-debug-tools)
+

--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/extensions/dbg_msg_timings/dbg_msg_timings.c	Fri May 10 13:26:03 2013 +0200
@@ -0,0 +1,134 @@
+/*********************************************************************************************************
+* Software License Agreement (BSD License)                                                               *
+* Author: Sebastien Decugis <sdecugis@freediameter.net>							 *
+*													 *
+* Copyright (c) 2013, WIDE Project and NICT								 *
+* All rights reserved.											 *
+* 													 *
+* Redistribution and use of this software in source and binary forms, with or without modification, are  *
+* permitted provided that the following conditions are met:						 *
+* 													 *
+* * Redistributions of source code must retain the above 						 *
+*   copyright notice, this list of conditions and the 							 *
+*   following disclaimer.										 *
+*    													 *
+* * Redistributions in binary form must reproduce the above 						 *
+*   copyright notice, this list of conditions and the 							 *
+*   following disclaimer in the documentation and/or other						 *
+*   materials provided with the distribution.								 *
+* 													 *
+* * Neither the name of the WIDE Project or NICT nor the 						 *
+*   names of its contributors may be used to endorse or 						 *
+*   promote products derived from this software without 						 *
+*   specific prior written permission of WIDE Project and 						 *
+*   NICT.												 *
+* 													 *
+* THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND ANY EXPRESS OR IMPLIED *
+* WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A *
+* PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR *
+* ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT 	 *
+* LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS 	 *
+* INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR *
+* TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF   *
+* ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.								 *
+*********************************************************************************************************/
+
+/* This extension uses the hooks mechanism to compute some timing information related to messages */
+
+#include <freeDiameter/extension.h>
+
+struct fd_hook_permsgdata {
+	struct timespec received_on;
+	struct timespec sent_on;
+};
+
+static struct fd_hook_data_hdl *mt_data_hdl = NULL;
+static struct fd_hook_hdl *mt_hdl = NULL;
+
+/* The callback called when messages are received and sent */
+static void mt_hook_cb(enum fd_hook_type type, struct msg * msg, struct peer_hdr * peer, void * other, struct fd_hook_permsgdata *pmd, void * regdata)
+{
+	struct msg_hdr * hdr;
+	char * buf = NULL;
+	size_t len;
+	
+	ASSERT(pmd);
+	
+	if (type == HOOK_DATA_RECEIVED) {
+		/* We just store the timestamp it was received on */
+		(void)clock_gettime(CLOCK_REALTIME, &pmd->received_on);
+		return;
+	}
+	
+	ASSERT(msg);
+	
+	/* Check if this message is request or answer */
+	CHECK_FCT_DO( fd_msg_hdr(msg, &hdr), return);
+	
+	if (type == HOOK_MESSAGE_RECEIVED) {
+		ASSERT(pmd->received_on.tv_sec); /* otherwise it means the HOOK_DATA_RECEIVED hook was not trigged for this message */
+		if (hdr->msg_flags & CMD_FLAG_REQUEST) {
+			/* We have received a new request, nothing special to do */
+		} else {
+			/* This is an answer, check how long it took to get it */
+			struct fd_hook_permsgdata *qpmd = fd_hook_get_request_pmd(mt_data_hdl, msg);
+			struct timespec delay;
+			ASSERT(qpmd); /* If we do not have it, we must find out why */
+			ASSERT(qpmd->sent_on.tv_sec); /* same, would mean the HOOK_MESSAGE_SENT hook was not trigged */
+			TS_DIFFERENCE( &delay, &qpmd->sent_on, &pmd->received_on );
+			CHECK_MALLOC_DO( fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), return );
+			LOG_N("[TIMING] RCV ANS %ld.%06ld sec: %s", (long)delay.tv_sec, delay.tv_nsec / 1000, buf);
+		}
+	} else if (type == HOOK_MESSAGE_SENT) {
+		DiamId_t source = NULL;
+		size_t slen = 0;
+		
+		(void)clock_gettime(CLOCK_REALTIME, &pmd->sent_on);
+		
+		/* Is this a forwarded message ? */
+		CHECK_FCT_DO( fd_msg_source_get(msg, &source, &slen), return );
+		if (source) {
+			struct timespec delay;
+			ASSERT(pmd->received_on.tv_sec);
+			TS_DIFFERENCE( &delay, &pmd->received_on, &pmd->sent_on );
+			CHECK_MALLOC_DO( fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), return );
+			LOG_N("[TIMING] FWD %ld.%06ld sec: %s", (long)delay.tv_sec, delay.tv_nsec / 1000, buf);
+		} else if (hdr->msg_flags & CMD_FLAG_REQUEST) {
+			/* We are sending a request issued locally, nothing special to log */
+		} else {
+			/* We have generated an anwer, log the time it took since the corresponding request was received */
+			struct fd_hook_permsgdata *qpmd = fd_hook_get_request_pmd(mt_data_hdl, msg);
+			if (qpmd->received_on.tv_sec) {
+				struct timespec delay;
+				TS_DIFFERENCE( &delay, &qpmd->received_on, &pmd->sent_on );
+				CHECK_MALLOC_DO( fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), return );
+				LOG_N("[TIMING] ANS %ld.%06ld sec: %s", (long)delay.tv_sec, delay.tv_nsec / 1000, buf);
+			}
+		}
+	}
+		
+	free(buf);
+}
+
+/* Entry point */
+static int mt_main(char * conffile)
+{
+	TRACE_ENTRY("%p", conffile);
+	
+	CHECK_FCT( fd_hook_data_register( sizeof(struct fd_hook_permsgdata), NULL, NULL, &mt_data_hdl ) );
+	
+	CHECK_FCT( fd_hook_register( ((1 << HOOK_MESSAGE_RECEIVED) | (1 << HOOK_MESSAGE_SENT) | (1 << HOOK_DATA_RECEIVED)), 
+					mt_hook_cb, NULL, mt_data_hdl, &mt_hdl) );
+	
+	return 0;
+}
+
+/* Cleanup */
+void fd_ext_fini(void)
+{
+	TRACE_ENTRY();
+	CHECK_FCT_DO( fd_hook_unregister( mt_hdl ), );
+	return ;
+}
+
+EXTENSION_ENTRY("dbg_msg_timing", mt_main);

--- a/include/freeDiameter/libfdcore.h	Fri May 10 13:24:23 2013 +0200
+++ b/include/freeDiameter/libfdcore.h	Fri May 10 13:26:03 2013 +0200
@@ -552,8 +552,13 @@
 int fd_msg_new_session( struct msg * msg, os0_t opt, size_t optlen );
 
 
-/* Parse a message against our dictionary, and in case of error log and eventually build the error reply (on return and EBADMSG, *msg == NULL or *msg is the error message ready to send) */
-int fd_msg_parse_or_error( struct msg ** msg );
+/* Parse a message against our dictionary, 
+	return 0 in case of success.
+	log parsing error & return error code in case of failure in parsing. 
+	In addition, if the error code is EBADMSG (the message does not follow our dictionary) 
+		if *msg was a request, *msg is NULL and *error contains the error message ready to send back on return
+		if *msg was an answer, *msg is untouched and *error==*msg if *msg was an error message, *error is null otherwise */
+int fd_msg_parse_or_error( struct msg ** msg, struct msg **error );
 
 
 
@@ -925,7 +930,7 @@
 		   try to call fd_msg_parse_dict, it will slow down the operation of a relay agent.
 		 - {peer} is set if the message is received from a peer's connection, and NULL if the message is from a new client
 		   connected and not yet identified
-		 - {other} is NULL.
+		 - {other} is NULL, or a char * identifying the connection when {peer} is null.
 		 - {permsgdata} points to either a new empty structure allocated for this message or the one passed to HOOK_DATA_RECEIVED if used.
 		 */
 	
@@ -958,10 +963,16 @@
 		 - {permsgdata} points to existing structure if any, or a new structure otherwise. 
 		 */
 	
+	HOOK_MESSAGE_PARSING_ERROR,
+		/* Hook called when a message being processed cannot be parsed successfully.
+		 - {msg} points to the message if buffer was parsed successfully, or NULL otherwise. You should not call fd_msg_parse_dict on this in any case.
+		 - {peer} is NULL or the peer that received the message. If NULL and the message is not NULL, you can still retrieve the source from the message itself.
+		 - {other} is a char * pointer to the error message (human-readable) if {msg} is not NULL, a pointer to struct fd_cnx_rcvdata containing the received buffer otherwise.
+		 - {permsgdata} points to existing structure associated with this message (or new structure if no previous hook was registered). 
+		 */
+	
 	HOOK_MESSAGE_ROUTING_ERROR,
-		/* Hook called when a message being processed by the routing thread meets an error such as:
-		     -- parsing error
-		     -- no remaining available peer for sending, based on routing callbacks decisions (maybe after retries).
+		/* Hook called when a message being processed by the routing thread meets an error such as no remaining available peer for sending, based on routing callbacks decisions (maybe after retries).
 		 - {msg} points to the message. Again, the objects may not have been dictionary resolved. If you
 		   try to call fd_msg_parse_dict, it might slow down the operation of a relay agent, although this hook is not on the normal execution path.
 		 - {peer} is NULL.
@@ -993,22 +1004,23 @@
 		/* Hook called when a message is being discarded by the framework because of some error condition (normal or abnormal).
 		   It is probably a good idea to log this for analysis / backup.
 		 - {msg} points to the message, which will be freed as soon as the hook returns.
-		 - {peer} is NULL.
+		 - {peer} may be NULL or a peer related to the event.
 		 - {other} is a char * pointer to the error message (human-readable).
 		 - {permsgdata} points to existing structure associated with this message (or new structure if no previous hook was registered).
 		 */
 	
 	HOOK_PEER_CONNECT_FAILED,
-		/* Hook called when a connection attempt to a remote peer has failed.
-		 - {msg} may be NULL (lower layer error, e.g. connection timeout) or points to the CEA message sent or received (with an error code).
+		/* Hook called when a connection attempt to/from a remote peer has failed. This hook is also called when the peer was in OPEN state and the connection is broken.
+		 - {msg} may be NULL (lower layer error, e.g. connection timeout) or points to a message showing the error (either invalid incoming message, or the CEA message sent or received with an error code).
 		 - {peer} may be NULL for incoming requests from unknown peers being rejected, otherwise it points to the peer structure associated with the attempt.
 		 - {other} is a char * pointer to the error message (human-readable).
 		 - {permsgdata} is always NULL for this hook.
 		 */
 	
 	HOOK_PEER_CONNECT_SUCCESS,
-		/* Hook called when a connection attempt to a remote peer has succeeded (the peer moves to OPEN state).
-		 - {msg} points to the CEA message sent or received (with an success code) -- in case it is sent, you can always get access to the matching CER.
+		/* Hook called when a connection attempt to/from a remote peer has succeeded (the peer moves to OPEN_HANDSHAKE or OPEN state).
+		    In case of deprecated TLS handshake after the CER/CEA exchange, this hook can still be followed by HOOK_PEER_CONNECT_FAILED if TLS handshake fails.
+		 - {msg} points to the CEA message sent or received (with a success code) -- in case it is sent, you can always get access to the matching CER.
 		 - {peer} points to the peer structure.
 		 - {other} is NULL.
 		 - {permsgdata} is always NULL for this hook.
@@ -1068,7 +1080,7 @@
  * FUNCTION:	fd_hook_register
  *
  * PARAMETERS:
- *  type_mask	  : A bitmask of fd_hook_type bits for which this cb is registered, e.g. ((1 << HOOK_MESSAGE_RECEIVED) || (1 << HOOK_MESSAGE_SENT))
+ *  type_mask	  : A bitmask of fd_hook_type bits for which this cb is registered, e.g. ((1 << HOOK_MESSAGE_RECEIVED) | (1 << HOOK_MESSAGE_SENT))
  *  fd_hook_cb	  : The callback function to register (see prototype above).
  *  regdata	  : Pointer to pass to the callback when it is called. The data is opaque to the daemon.
  *  data_hdl      : If permsgdata is requested for the hooks, a handler registered with fd_hook_data_register. NULL otherwise.
@@ -1094,6 +1106,10 @@
 int fd_hook_unregister( struct fd_hook_hdl * handler );
 
 
+/* Use the following function to retrieve any pmd structure associated with a request matching the current answer. Returns NULL in case of error / no such structure */
+struct fd_hook_permsgdata * fd_hook_get_request_pmd(struct fd_hook_data_hdl *data_hdl, struct msg * answer);
+
+
 /*============================================================*/
 
 /*

--- a/include/freeDiameter/libfdproto.h	Fri May 10 13:24:23 2013 +0200
+++ b/include/freeDiameter/libfdproto.h	Fri May 10 13:26:03 2013 +0200
@@ -145,7 +145,9 @@
  *  None.
  */
 void fd_log ( int, const char *, ... ) _ATTRIBUTE_PRINTFLIKE_(2,3);
+#ifndef SWIG
 void fd_log_va( int, const char *, va_list args );
+#endif /* SWIG */
 
 /* these are internal objects of the debug facility, 
 might be useful to control the behavior from outside */
@@ -608,6 +610,8 @@
 
 DECLARE_FD_DUMP_PROTOTYPE(fd_sa_dump_node, sSA * sa, int flags);
 DECLARE_FD_DUMP_PROTOTYPE(fd_sa_dump_node_serv, sSA * sa, int flags);
+#define sSA_DUMP_STRLEN	(INET6_ADDRSTRLEN + 1 + 32 + 2)
+void fd_sa_sdump_numeric(char * buf /* must be at least sSA_DUMP_STRLEN */, sSA * sa);
 
 
 /* A l4 protocol name (TCP / SCTP) */

--- a/libfdcore/cnxctx.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/cnxctx.c	Fri May 10 13:26:03 2013 +0200
@@ -227,12 +227,6 @@
 	/* Accept the new connection -- this is blocking until new client enters or until cancellation */
 	CHECK_SYS_DO( cli_sock = accept(serv->cc_socket, (sSA *)&ss, &ss_len), return NULL );
 	
-	if (TRACE_BOOL(INFO)) {
-		char buf[1024];
-		sSA_DUMP_NODE( buf, sizeof(buf), &ss, NI_NUMERICHOST );
-		fd_log_debug("%s : accepted new client [%s].", fd_cnx_getid(serv), buf);
-	}
-	
 	CHECK_MALLOC_DO( cli = fd_cnx_init(1), { shutdown(cli_sock, SHUT_RDWR); close(cli_sock); return NULL; } );
 	cli->cc_socket = cli_sock;
 	cli->cc_family = serv->cc_family;
@@ -263,6 +257,8 @@
 		if (rc)
 			snprintf(cli->cc_remid, sizeof(cli->cc_remid), "[err:%s]", gai_strerror(rc));
 	}
+	
+	LOG_D("Incoming connection: '%s' <- '%s'   {%s}", fd_cnx_getid(serv), cli->cc_remid, cli->cc_id);
 
 #ifndef DISABLE_SCTP
 	/* SCTP-specific handlings */
@@ -274,7 +270,7 @@
 		else
 			cli->cc_sctp_para.pairs = cli->cc_sctp_para.str_in;
 		
-		TRACE_DEBUG(FULL,"%s : client '%s' (SCTP:%d, %d/%d streams)", fd_cnx_getid(serv), fd_cnx_getid(cli), cli->cc_socket, cli->cc_sctp_para.str_in, cli->cc_sctp_para.str_out);
+		LOG_A( "%s : client '%s' (SCTP:%d, %d/%d streams)", fd_cnx_getid(serv), fd_cnx_getid(cli), cli->cc_socket, cli->cc_sctp_para.str_in, cli->cc_sctp_para.str_out);
 	}
 #endif /* DISABLE_SCTP */
 
@@ -286,36 +282,22 @@
 {
 	int sock = 0;
 	struct cnxctx * cnx = NULL;
+	char sa_buf[sSA_DUMP_STRLEN];
 	
 	TRACE_ENTRY("%p %d", sa, addrlen);
 	CHECK_PARAMS_DO( sa && addrlen, return NULL );
 	
+	fd_sa_sdump_numeric(sa_buf, sa);
+	
 	/* Create the socket and connect, which can take some time and/or fail */
 	{
 		int ret = fd_tcp_client( &sock, sa, addrlen );
 		if (ret != 0) {
-			int lvl;
-			switch (ret) {
-				case ECONNREFUSED:
-
-					/* "Normal" errors */
-					lvl = FULL;
-					break;
-				default:
-					lvl = INFO;
-			}
-			/* Some errors are expected, we log at different level */
-			TRACE_DEBUG( lvl, "fd_tcp_client returned an error: %s", strerror(ret));
+			LOG_A("TCP connection to %s failed: %s", sa_buf, strerror(ret));
 			return NULL;
 		}
 	}
 	
-	if (TRACE_BOOL(INFO)) {
-		char buf[1024];
-		sSA_DUMP_NODE_SERV( buf, sizeof(buf), sa, NI_NUMERICSERV);
-		fd_log_debug("Connection established to server '%s' (TCP:%d).", buf, sock);
-	}
-	
 	/* Once the socket is created successfuly, prepare the remaining of the cnx */
 	CHECK_MALLOC_DO( cnx = fd_cnx_init(1), { shutdown(sock, SHUT_RDWR); close(sock); return NULL; } );
 	
@@ -328,18 +310,9 @@
 	
 	/* Generate the names for the object */
 	{
-		char addrbuf[INET6_ADDRSTRLEN];
-		char portbuf[10];
 		int  rc;
 		
-		/* Numeric values for debug... */
-		rc = getnameinfo(sa, addrlen, addrbuf, sizeof(addrbuf), portbuf, sizeof(portbuf), NI_NUMERICHOST | NI_NUMERICSERV);
-		if (rc) {
-			snprintf(addrbuf, sizeof(addrbuf), "[err:%s]", gai_strerror(rc));
-			portbuf[0] = '\0';
-		}
-		
-		snprintf(cnx->cc_id, sizeof(cnx->cc_id), "TCP to [%s]:%s (%d)", addrbuf, portbuf, cnx->cc_socket);
+		snprintf(cnx->cc_id, sizeof(cnx->cc_id), "TCP,#%d->%s", cnx->cc_socket, sa_buf);
 		
 		/* ...Name for log messages */
 		rc = getnameinfo(sa, addrlen, cnx->cc_remid, sizeof(cnx->cc_remid), NULL, 0, 0);
@@ -347,6 +320,8 @@
 			snprintf(cnx->cc_remid, sizeof(cnx->cc_remid), "[err:%s]", gai_strerror(rc));
 	}
 	
+	LOG_A("TCP connection to %s succeed (socket:%d).", sa_buf, sock);
+	
 	return cnx;
 }
 
@@ -361,26 +336,18 @@
 #else /* DISABLE_SCTP */
 	int sock = 0;
 	struct cnxctx * cnx = NULL;
+	char sa_buf[sSA_DUMP_STRLEN];
 	sSS primary;
 	
 	TRACE_ENTRY("%p", list);
 	CHECK_PARAMS_DO( list && !FD_IS_LIST_EMPTY(list), return NULL );
 	
+	fd_sa_sdump_numeric(sa_buf, &((struct fd_endpoint *)(list->next))->sa);
+	
 	{
 		int ret = fd_sctp_client( &sock, no_ip6, port, list );
 		if (ret != 0) {
-			int lvl;
-			switch (ret) {
-				case ECONNREFUSED:
-
-					/* "Normal" errors */
-					lvl = FULL;
-					break;
-				default:
-					lvl = INFO;
-			}
-			/* Some errors are expected, we log at different level */
-			TRACE_DEBUG( lvl, "fd_sctp_client returned an error: %s", strerror(ret));
+			LOG_A("SCTP connection to [%s,...] failed: %s", sa_buf, strerror(ret));
 			return NULL;
 		}
 	}
@@ -402,26 +369,13 @@
 	else
 		cnx->cc_sctp_para.pairs = cnx->cc_sctp_para.str_in;
 	
-	if (TRACE_BOOL(INFO)) {
-		char buf[1024];
-		sSA_DUMP_NODE_SERV( buf, sizeof(buf), &primary, NI_NUMERICSERV);
-		fd_log_debug("Connection established to server '%s' (SCTP:%d, %d/%d streams).", buf, sock, cnx->cc_sctp_para.str_in, cnx->cc_sctp_para.str_out);
-	}
+	fd_sa_sdump_numeric(sa_buf, (sSA *)&primary);
 	
 	/* Generate the names for the object */
 	{
-		char addrbuf[INET6_ADDRSTRLEN];
-		char portbuf[10];
 		int  rc;
 		
-		/* Numeric values for debug... */
-		rc = getnameinfo((sSA *)&primary, sSAlen(&primary), addrbuf, sizeof(addrbuf), portbuf, sizeof(portbuf), NI_NUMERICHOST | NI_NUMERICSERV);
-		if (rc) {
-			snprintf(addrbuf, sizeof(addrbuf), "[err:%s]", gai_strerror(rc));
-			portbuf[0] = '\0';
-		}
-		
-		snprintf(cnx->cc_id, sizeof(cnx->cc_id), "SCTP to [%s]:%s (%d)", addrbuf, portbuf, cnx->cc_socket);
+		snprintf(cnx->cc_id, sizeof(cnx->cc_id), "SCTP,#%d->%s", cnx->cc_socket, sa_buf);
 		
 		/* ...Name for log messages */
 		rc = getnameinfo((sSA *)&primary, sSAlen(&primary), cnx->cc_remid, sizeof(cnx->cc_remid), NULL, 0, 0);
@@ -429,6 +383,8 @@
 			snprintf(cnx->cc_remid, sizeof(cnx->cc_remid), "[err:%s]", gai_strerror(rc));
 	}
 	
+	LOG_A("SCTP connection to %s succeed (socket:%d, %d/%d streams).", sa_buf, sock, cnx->cc_sctp_para.str_in, cnx->cc_sctp_para.str_out);
+	
 	return cnx;
 
 error:
@@ -677,7 +633,7 @@
 
 size_t fd_msg_pmdl_sizewithoverhead(size_t datalen)
 {
-	return PMDL_PADDED(datalen);
+	return PMDL_PADDED(datalen) + sizeof(struct fd_msg_pmdl);
 }
 
 struct fd_msg_pmdl * fd_msg_pmdl_get_inbuf(uint8_t * buf, size_t datalen)
@@ -697,7 +653,7 @@
 {
 	uint8_t * ret = NULL;
 	
-	CHECK_MALLOC_DO(  ret = malloc( PMDL_PADDED(expected_len) ), return NULL );
+	CHECK_MALLOC_DO(  ret = malloc( fd_msg_pmdl_sizewithoverhead(expected_len) ), return NULL );
 	CHECK_FCT_DO( fd_cnx_init_msg_buffer(ret, expected_len, pmdl), {free(ret); return NULL;} );
 	return ret;
 }
@@ -706,7 +662,7 @@
 {
 	uint8_t * ret = NULL;
 	
-	CHECK_MALLOC_DO(  ret = realloc( buffer, PMDL_PADDED(expected_len) ), return NULL );
+	CHECK_MALLOC_DO(  ret = realloc( buffer, fd_msg_pmdl_sizewithoverhead(expected_len) ), return NULL );
 	CHECK_FCT_DO( fd_cnx_init_msg_buffer(ret, expected_len, pmdl), {free(ret); return NULL;} );
 	return ret;
 }
@@ -761,7 +717,7 @@
 		if ((header[0] != DIAMETER_VERSION)	/* defined in <libfdproto.h> */
 		   || (rcv_data.length > DIAMETER_MSG_SIZE_MAX)) { /* to avoid too big mallocs */
 			/* The message is suspect */
-			LOG_E( "Received suspect header [ver: %d, size: %zd], assuming disconnection", (int)header[0], rcv_data.length);
+			LOG_E( "Received suspect header [ver: %d, size: %zd] from '%s', assuming disconnection", (int)header[0], rcv_data.length, conn->cc_remid);
 			fd_cnx_markerror(conn);
 			goto out; /* Stop the thread, the recipient of the event will cleanup */
 		}
@@ -1003,7 +959,7 @@
 		if ((header[0] != DIAMETER_VERSION)	/* defined in <libfreeDiameter.h> */
 		   || (rcv_data.length > DIAMETER_MSG_SIZE_MAX)) { /* to avoid too big mallocs */
 			/* The message is suspect */
-			LOG_E( "Received suspect header [ver: %d, size: %zd], assume disconnection", (int)header[0], rcv_data.length);
+			LOG_E( "Received suspect header [ver: %d, size: %zd] from '%s', assume disconnection", (int)header[0], rcv_data.length, conn->cc_remid);
 			fd_cnx_markerror(conn);
 			goto out;
 		}

--- a/libfdcore/hooks.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/hooks.c	Fri May 10 13:26:03 2013 +0200
@@ -185,8 +185,7 @@
 	CHECK_PARAMS_DO( msg && pmdl, return );
 	in_msg = fd_msg_pmdl_get(msg);
 	ASSERT(in_msg && (in_msg->sentinel.o == NULL)); /* error / already initialized ??? */
-	fd_list_init(&in_msg->sentinel, pmdl_free);
-	CHECK_POSIX_DO( pthread_mutex_init(&in_msg->lock, NULL), );
+	in_msg->sentinel.o = pmdl_free;
 	/* Now move all items from the pmdl pointer into the initialized list */
 	CHECK_POSIX_DO( pthread_mutex_lock(&pmdl->lock), );
 	fd_list_move_end(&in_msg->sentinel, &pmdl->sentinel);
@@ -200,8 +199,13 @@
 {
 	struct fd_hook_permsgdata * ret = NULL;
 	struct fd_list * li;
+	
 	CHECK_POSIX_DO( pthread_mutex_lock(&pmdl->lock), );
 	
+	if (pmdl->sentinel.o == NULL) {
+		pmdl->sentinel.o = pmdl_free;
+	}
+	
 	/* Search in the list for an item with the same handle. The list is ordered by this handle */
 	for (li=pmdl->sentinel.next; li != &pmdl->sentinel; li = li->next) {
 		struct pmd_list_item * pli = (struct pmd_list_item *) li;
@@ -230,30 +234,175 @@
 	return ret;
 }
 
+struct fd_hook_permsgdata * fd_hook_get_request_pmd(struct fd_hook_data_hdl *data_hdl, struct msg * answer)
+{
+	struct msg * qry;
+	struct fd_msg_pmdl *pmdl;
+	struct fd_hook_permsgdata * ret = NULL;
+	struct fd_list * li;
+	
+	CHECK_FCT_DO( fd_msg_answ_getq(answer, &qry), return NULL );
+	if (!qry)
+		return NULL;
+	
+	pmdl = fd_msg_pmdl_get(qry);
+	if (!pmdl)
+		return NULL;
+	
+	CHECK_POSIX_DO( pthread_mutex_lock(&pmdl->lock), );
+	/* Search in the list for an item with the same handle. The list is ordered by this handle */
+	for (li=pmdl->sentinel.next; li != &pmdl->sentinel; li = li->next) {
+		struct pmd_list_item * pli = (struct pmd_list_item *) li;
+		if (pli->hdl == data_hdl)
+			ret = &pli->pmd;
+		if (pli->hdl >= data_hdl)
+			break;
+	}
+	CHECK_POSIX_DO( pthread_mutex_unlock(&pmdl->lock), );
+	return ret;
+}
 
 /* The function that does the work of calling the extension's callbacks and also managing the permessagedata structures */
 void   fd_hook_call(enum fd_hook_type type, struct msg * msg, struct fd_peer * peer, void * other, struct fd_msg_pmdl * pmdl)
 {
 	struct fd_list * li;
 	ASSERT(type <= HOOK_PEER_LAST);
+	int call_default = 0;
 	
 	/* lock the list of hooks for this type */
 	CHECK_POSIX_DO( pthread_rwlock_rdlock(&HS_array[type].rwlock), );
 	
-	/* for each registered hook */
-	for (li = HS_array[type].sentinel.next; li != &HS_array[type].sentinel; li = li->next) {
-		struct fd_hook_hdl * h = (struct fd_hook_hdl *)li->o;
-		struct fd_hook_permsgdata * pmd = NULL;
-		
-		/* do we need to handle pmd ? */
-		if (h->data_hdl && pmdl) {
-			pmd = get_or_create_pmd(pmdl, h);
+	if (FD_IS_LIST_EMPTY(&HS_array[type].sentinel)) {
+		call_default = 1;
+	} else {
+		/* for each registered hook */
+		for (li = HS_array[type].sentinel.next; li != &HS_array[type].sentinel; li = li->next) {
+			struct fd_hook_hdl * h = (struct fd_hook_hdl *)li->o;
+			struct fd_hook_permsgdata * pmd = NULL;
+
+			/* do we need to handle pmd ? */
+			if (h->data_hdl && pmdl) {
+				pmd = get_or_create_pmd(pmdl, h);
+			}
+
+			/* Now, call this callback */
+			(*h->fd_hook_cb)(type, msg, &peer->p_hdr, other, pmd, h->regdata);
 		}
-		
-		/* Now, call this callback */
-		(*h->fd_hook_cb)(type, msg, &peer->p_hdr, other, pmd, h->regdata);
 	}
 	
 	/* done */
 	CHECK_POSIX_DO( pthread_rwlock_unlock(&HS_array[type].rwlock), );
+	
+	if (call_default) {
+		char * buf = NULL;
+		size_t len = 0;
+	
+		/* There was no registered handler, default behavior for this hook */
+		switch (type) {
+			case HOOK_DATA_RECEIVED: {
+				struct fd_cnx_rcvdata *rcv_data = other;
+				LOG_A("RCV: %zd bytes", rcv_data->length);
+				break;
+			}
+			
+			case HOOK_MESSAGE_RECEIVED: {
+				CHECK_MALLOC_DO(fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_D("RCV from '%s': %s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_LOCAL: {
+				CHECK_MALLOC_DO(fd_msg_dump_full(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_A("Handled to framework for sending: %s", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_SENT: {
+				CHECK_MALLOC_DO(fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_D("SENT to '%s': %s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_FAILOVER: {
+				CHECK_MALLOC_DO(fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_D("Failing over message sent to '%s': %s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_PARSING_ERROR: {
+				if (msg) {
+					DiamId_t id = NULL;
+					size_t idlen;
+					if (!fd_msg_source_get( msg, &id, &idlen ))
+						id = (DiamId_t)"<error getting source>";
+					
+					if (!id)
+						id = (DiamId_t)"<local>";
+					
+					CHECK_MALLOC_DO(fd_msg_dump_treeview(&buf, &len, NULL, msg, NULL, 0, 1), break);
+					
+					LOG_E("Parsing error: '%s' for the following message received from '%s':\n%s", (char *)other, (char *)id, buf);
+				} else {
+					struct fd_cnx_rcvdata *rcv_data = other;
+					CHECK_MALLOC_DO(fd_dump_extend_hexdump(&buf, &len, NULL, rcv_data->buffer, rcv_data->length, 0, 0), break);
+					LOG_E("Parsing error: cannot parse %zdB buffer from '%s': %s",  rcv_data->length, peer ? peer->p_hdr.info.pi_diamid : "<unknown>", buf);
+				}
+				break;
+			}
+			
+			case HOOK_MESSAGE_ROUTING_ERROR: {
+				DiamId_t id = NULL;
+				size_t idlen;
+				if (!fd_msg_source_get( msg, &id, &idlen ))
+					id = (DiamId_t)"<error getting source>";
+
+				if (!id)
+					id = (DiamId_t)"<local>";
+
+				CHECK_MALLOC_DO(fd_msg_dump_treeview(&buf, &len, NULL, msg, NULL, 0, 1), break);
+
+				LOG_E("Routing error: '%s' for the following message:\n%s", (char *)other, buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_ROUTING_FORWARD: {
+				CHECK_MALLOC_DO(fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_D("FORWARDING: %s", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_ROUTING_LOCAL: {
+				CHECK_MALLOC_DO(fd_msg_dump_summary(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_D("DISPATCHING: %s", buf);
+				break;
+			}
+			
+			case HOOK_MESSAGE_DROPPED: {
+				CHECK_MALLOC_DO(fd_msg_dump_treeview(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_E("Message discarded ('%s'):\n%s", (char *)other, buf);
+				break;
+			}
+			
+			case HOOK_PEER_CONNECT_FAILED: {
+				if (msg) {
+					size_t offset = 0;
+					CHECK_MALLOC_DO(fd_dump_extend(&buf, &len, &offset, " CER/CEA dump:\n"), break);
+					CHECK_MALLOC_DO(fd_msg_dump_treeview(&buf, &len, &offset, msg, NULL, 0, 1), break);
+					LOG_N("Connection to '%s' failed: %s%s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", (char *)other, buf);
+				} else {
+					LOG_D("Connection to '%s' failed: %s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", (char *)other);
+				}
+				break;
+			}
+			
+			case HOOK_PEER_CONNECT_SUCCESS: {
+				CHECK_MALLOC_DO(fd_msg_dump_treeview(&buf, &len, NULL, msg, NULL, 0, 1), break);
+				LOG_N("Connected to '%s', remote capabilities: %s", peer ? peer->p_hdr.info.pi_diamid : "<unknown>", buf);
+				break;
+			}
+			
+		}
+		
+		free(buf);
+	}
 }

--- a/libfdcore/messages.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/messages.c	Fri May 10 13:26:03 2013 +0200
@@ -345,7 +345,7 @@
 
 
 /* Parse a message against our dictionary, and in case of error log and eventually build the error reply -- returns the parsing status */
-int fd_msg_parse_or_error( struct msg ** msg )
+int fd_msg_parse_or_error( struct msg ** msg, struct msg **error)
 {
 	int ret = 0;
 	struct msg * m;
@@ -354,8 +354,9 @@
 	
 	TRACE_ENTRY("%p", msg);
 	
-	CHECK_PARAMS(msg && *msg);
+	CHECK_PARAMS(msg && *msg && error);
 	m = *msg;
+	*error = NULL;
 	
 	/* Parse the message against our dictionary */
 	ret = fd_msg_parse_rules ( m, fd_g_config->cnf_dict, &pei);
@@ -363,8 +364,8 @@
 		&& (ret != ENOTSUP))	/* Command is not supported / Mandatory AVP is not supported */
 		return ret; /* 0 or another error */
 	
-	TRACE_DEBUG(INFO, "A message does not comply to the dictionary and/or rules (%s)", pei.pei_errcode);
-	fd_msg_dump_walk(FULL, m);
+	/* Log */
+	fd_hook_call(HOOK_MESSAGE_PARSING_ERROR, m, NULL, pei.pei_message ?: pei.pei_errcode, fd_msg_pmdl_get(m));
 	
 	CHECK_FCT( fd_msg_hdr(m, &hdr) );
 	
@@ -372,10 +373,13 @@
 	if (hdr->msg_flags & CMD_FLAG_REQUEST) {
 		
 		/* Create the error message */
-		CHECK_FCT( fd_msg_new_answer_from_req ( fd_g_config->cnf_dict, msg, pei.pei_protoerr ? MSGFL_ANSW_ERROR : 0 ) );
+		CHECK_FCT( fd_msg_new_answer_from_req ( fd_g_config->cnf_dict, &m, pei.pei_protoerr ? MSGFL_ANSW_ERROR : 0 ) );
 		
 		/* Set the error code */
-		CHECK_FCT( fd_msg_rescode_set(*msg, pei.pei_errcode, pei.pei_message, pei.pei_avp, 1 ) );
+		CHECK_FCT( fd_msg_rescode_set(m, pei.pei_errcode, pei.pei_message, pei.pei_avp, 1 ) );
+		
+		*msg = NULL;
+		*error = m;
 		
 	} else {
 		do { /* Rescue error messages */
@@ -408,15 +412,10 @@
 						
 					default: /* Other errors */
 						/* We let the application decide what to do with the message, we rescue it */
-						return 0;
+						*error = m;
 				}
 			}
 		} 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;
 	}
 	
 	return EBADMSG; /* We convert ENOTSUP to EBADMSG as well */

--- a/libfdcore/p_ce.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/p_ce.c	Fri May 10 13:26:03 2013 +0200
@@ -670,6 +670,8 @@
 			/* Close initiator connection */
 			fd_cnx_destroy(initiator);
 
+			LOG_D("%s: Election lost on outgoing connection, closing and answering CEA on incoming connection.", peer->p_hdr.info.pi_diamid);
+			
 			/* Process with the receiver side */
 			CHECK_FCT( fd_p_ce_process_receiver(peer) );
 
@@ -677,6 +679,8 @@
 			struct fd_pei pei;
 			memset(&pei, 0, sizeof(pei));
 			pei.pei_errcode = "ELECTION_LOST";
+			pei.pei_message = "Please answer my CER instead, you won the election.";
+			LOG_D("%s: Election lost on incoming connection, closing and waiting for CEA on outgoing connection.", peer->p_hdr.info.pi_diamid);
 
 			/* Answer an ELECTION LOST to the receiver side */
 			receiver_reject(&peer->p_receiver, &peer->p_cer, &pei);
@@ -719,7 +723,11 @@
 	/* If the state is not WAITCEA, just discard the message */
 	if (req || ((st = fd_peer_getstate(peer)) != STATE_WAITCEA)) {
 		if (*msg) {
-			//fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.", STATE_STR(st));
+			/* In such case, just discard the message */
+			char buf[128];
+			snprintf(buf, sizeof(buf), "Received while peer state machine was in state %s.", STATE_STR(st));
+			fd_hook_call(HOOK_MESSAGE_DROPPED, *msg, peer, buf, fd_msg_pmdl_get(*msg));
+
 			CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
 			*msg = NULL;
 		}
@@ -730,21 +738,28 @@
 	memset(&pei, 0, sizeof(pei));
 	
 	/* Save info from the CEA into the peer */
-	CHECK_FCT_DO( save_remote_CE_info(*msg, peer, &pei, &rc), goto cleanup );
-	
-	/* Dispose of the message, we don't need it anymore */
-	CHECK_FCT_DO( fd_msg_free(*msg), /* continue */ );
-	*msg = NULL;
+	CHECK_FCT_DO( save_remote_CE_info(*msg, peer, &pei, &rc), 
+		{
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, *msg, peer, "An error occurred while processing incoming CEA.", NULL);
+			goto cleanup;
+		} );
 	
 	/* Check the Result-Code */
 	switch (rc) {
 		case ER_DIAMETER_SUCCESS:
+			/* Log success */
+			fd_hook_call(HOOK_PEER_CONNECT_SUCCESS, *msg, peer, NULL, NULL);
+			
+			/* Dispose of the message, we don't need it anymore */
+			CHECK_FCT_DO( fd_msg_free(*msg), /* continue */ );
+			*msg = NULL;
+			
 			/* No problem, we can continue */
 			break;
 			
 		case ER_DIAMETER_TOO_BUSY:
 			/* Retry later */
-			TRACE_DEBUG(INFO, "Peer %s replied a CEA with Result-Code AVP DIAMETER_TOO_BUSY, will retry later.", peer->p_hdr.info.pi_diamid);
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, *msg, peer, "Remote peer is too busy", NULL);
 			fd_psm_cleanup(peer, 0);
 			fd_psm_next_timeout(peer, 0, 300);
 			return 0;
@@ -756,10 +771,11 @@
 		
 		default:
 			/* In any other case, we abort all attempts to connect to this peer */
-			TRACE_DEBUG(INFO, "Peer %s replied a CEA with Result-Code %d, aborting connection attempts.", peer->p_hdr.info.pi_diamid, rc);
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, *msg, peer, "CEA with unexpected error code", NULL);
 			return EINVAL;
 	}
 	
+	
 	/* Handshake if needed, start clear otherwise */
 	if ( ! fd_cnx_getTLS(peer->p_cnxctx) ) {
 		int todo = peer->p_hdr.info.config.pic_flags.sec & peer->p_hdr.info.runtime.pir_isi ;
@@ -777,7 +793,7 @@
 			CHECK_FCT_DO( fd_cnx_handshake(peer->p_cnxctx, GNUTLS_CLIENT, peer->p_hdr.info.config.pic_priority, NULL),
 				{
 					/* Handshake failed ...  */
-					fd_log_debug("TLS Handshake failed with peer '%s', resetting the connection", peer->p_hdr.info.pi_diamid);
+					fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "TLS handshake failed after CER/CEA exchange", NULL);
 					goto cleanup;
 				} );
 
@@ -817,7 +833,11 @@
 	
 	TRACE_ENTRY("%p", peer);
 	
-	CHECK_FCT( set_peer_cnx(peer, &peer->p_receiver) );
+	CHECK_FCT_DO( set_peer_cnx(peer, &peer->p_receiver),
+		{
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "Error saving the incoming connection in the peer structure", NULL);
+			return __ret__;
+		} );
 	msg = peer->p_cer;
 	peer->p_cer = NULL;
 	
@@ -927,6 +947,10 @@
 	CHECK_FCT( fd_msg_new_answer_from_req ( fd_g_config->cnf_dict, &msg, 0 ) );
 	CHECK_FCT( fd_msg_rescode_set(msg, "DIAMETER_SUCCESS", NULL, NULL, 0 ) );
 	CHECK_FCT( add_CE_info(msg, peer->p_cnxctx, isi & PI_SEC_TLS_OLD, isi & PI_SEC_NONE) );
+	
+	/* The connection is complete, but we may still need TLS handshake */
+	fd_hook_call(HOOK_PEER_CONNECT_SUCCESS, msg, peer, NULL, NULL);
+	
 	CHECK_FCT( fd_out_send(&msg, peer->p_cnxctx, peer, FD_CNX_ORDERED ) );
 	
 	/* Handshake if needed */
@@ -935,19 +959,25 @@
 		CHECK_FCT_DO( fd_cnx_handshake(peer->p_cnxctx, GNUTLS_SERVER, peer->p_hdr.info.config.pic_priority, NULL),
 			{
 				/* Handshake failed ...  */
-				fd_log_debug("TLS Handshake failed with peer '%s', resetting the connection", peer->p_hdr.info.pi_diamid);
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "TLS handshake failed after CER/CEA exchange", NULL);
 				goto cleanup;
 			} );
 		
 		/* Retrieve the credentials */
-		CHECK_FCT( fd_cnx_getcred(peer->p_cnxctx, &peer->p_hdr.info.runtime.pir_cert_list, &peer->p_hdr.info.runtime.pir_cert_list_size) );
+		CHECK_FCT_DO( fd_cnx_getcred(peer->p_cnxctx, &peer->p_hdr.info.runtime.pir_cert_list, &peer->p_hdr.info.runtime.pir_cert_list_size),
+			{
+				/* Error ...  */
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "Unable to retrieve remote credentials after TLS handshake", NULL);
+				goto cleanup;
+			} );
+		
 		
 		/* Call second validation callback if needed */
 		if (peer->p_cb2) {
 			TRACE_DEBUG(FULL, "Calling second validation callback for %s", peer->p_hdr.info.pi_diamid);
 			CHECK_FCT_DO( (*peer->p_cb2)( &peer->p_hdr.info ),
 				{
-					TRACE_DEBUG(INFO, "Validation callback rejected the peer %s after handshake", peer->p_hdr.info.pi_diamid);
+					fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "Validation callback rejected the peer after handshake", NULL);
 					CHECK_FCT( fd_psm_terminate( peer, "DO_NOT_WANT_TO_TALK_TO_YOU" ) );
 					return 0;
 				}  );
@@ -981,12 +1011,16 @@
 error_abort:
 	if (pei.pei_errcode) {
 		/* Send the error */
+		fd_hook_call(HOOK_PEER_CONNECT_FAILED, msg, peer, pei.pei_message ?: pei.pei_errcode, NULL);
 		receiver_reject(&peer->p_cnxctx, &msg, &pei);
+	} else {
+		char buf[1024];
+		snprintf(buf, sizeof(buf), "Unexpected error occurred while processing incoming connection from '%s'.", peer->p_hdr.info.pi_diamid);
+		fd_hook_call(HOOK_PEER_CONNECT_FAILED, msg, peer, buf, NULL);
 	}
 	
 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);
@@ -1026,6 +1060,7 @@
 			if (election_result(peer)) {
 				
 				/* Close initiator connection (was already set as principal) */
+				LOG_D("%s: Election lost on outgoing connection, closing and answering CEA on incoming connection.", peer->p_hdr.info.pi_diamid);
 				fd_p_ce_clear_cnx(peer, NULL);
 				
 				/* and go on with the receiver side */
@@ -1040,6 +1075,7 @@
 				/* Answer an ELECTION LOST to the receiver side and continue */
 				pei.pei_errcode = "ELECTION_LOST";
 				pei.pei_message = "Please answer my CER instead, you won the election.";
+				LOG_D("%s: Election lost on incoming connection, closing and waiting for CEA on outgoing connection.", peer->p_hdr.info.pi_diamid);
 				receiver_reject(cnx, msg, &pei);
 			}
 			break;
@@ -1047,6 +1083,7 @@
 		default:
 			pei.pei_errcode = "DIAMETER_UNABLE_TO_COMPLY"; /* INVALID COMMAND? in case of Capabilities-Updates? */
 			pei.pei_message = "Invalid state to receive a new connection attempt.";
+			LOG_E("%s: Rejecting new connection attempt while our state machine is in state '%s'", peer->p_hdr.info.pi_diamid, STATE_STR(cur_state));
 			receiver_reject(cnx, msg, &pei);
 	}
 				

--- a/libfdcore/p_cnx.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/p_cnx.c	Fri May 10 13:26:03 2013 +0200
@@ -235,7 +235,8 @@
 			}
 			if (FD_IS_LIST_EMPTY(&peer->p_connparams)) {
 				/* We encountered an error or we have looped over all the addresses of the peer. */
-				TRACE_DEBUG(INFO, "Unable to connect to the peer %s, aborting attempts for now.", peer->p_hdr.info.pi_diamid);
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "All connection attempts failed, will retry later", NULL);
+				
 				CHECK_FCT_DO( fatal_error = fd_event_send(peer->p_events, FDEVP_CNX_FAILED, 0, NULL), goto out );
 				return NULL;
 			}
@@ -278,12 +279,13 @@
 		CHECK_FCT_DO( fd_cnx_handshake(cnx, GNUTLS_CLIENT, peer->p_hdr.info.config.pic_priority, NULL),
 			{
 				/* Handshake failed ...  */
-				TRACE_DEBUG(INFO, "TLS Handshake failed with peer '%s', resetting the connection", peer->p_hdr.info.pi_diamid);
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "TLS Handshake failed", NULL);
 				fd_cnx_destroy(cnx);
 				empty_connection_list(peer);
 				fd_ep_filter(&peer->p_hdr.info.pi_endpoints, EP_FL_CONF);
 				goto out_pop;
 			} );
+		LOG_A("%s: TLS handshake successful.", peer->p_hdr.info.pi_diamid);
 	} else {
 		/* Prepare to receive the next message */
 		CHECK_FCT_DO( fatal_error = fd_cnx_start_clear(cnx, 0), goto out_pop );

--- a/libfdcore/p_out.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/p_out.c	Fri May 10 13:26:03 2013 +0200
@@ -36,7 +36,7 @@
 #include "fdcore-internal.h"
 
 /* Alloc a new hbh for requests, bufferize the message and send on the connection, save in sentreq if provided */
-static int do_send(struct msg ** msg, uint32_t flags, struct cnxctx * cnx, uint32_t * hbh, struct sr_list * srl)
+static int do_send(struct msg ** msg, uint32_t flags, struct cnxctx * cnx, uint32_t * hbh, struct fd_peer * peer)
 {
 	struct msg_hdr * hdr;
 	int msg_is_a_req;
@@ -44,15 +44,16 @@
 	size_t sz;
 	int ret;
 	uint32_t bkp_hbh = 0;
+	struct msg *cpy_for_logs_only;
 	
-	TRACE_ENTRY("%p %x %p %p %p", msg, flags, cnx, hbh, srl);
+	TRACE_ENTRY("%p %x %p %p %p", msg, flags, cnx, hbh, peer);
 	
 	/* Retrieve the message header */
 	CHECK_FCT( fd_msg_hdr(*msg, &hdr) );
 	
 	msg_is_a_req = (hdr->msg_flags & CMD_FLAG_REQUEST);
 	if (msg_is_a_req) {
-		CHECK_PARAMS(hbh && srl);
+		CHECK_PARAMS(hbh && peer);
 		/* Alloc the hop-by-hop id and increment the value for next message */
 		bkp_hbh = hdr->msg_hbhid;
 		hdr->msg_hbhid = *hbh;
@@ -63,15 +64,15 @@
 	CHECK_FCT(fd_msg_bufferize( *msg, &buf, &sz ));
 	pthread_cleanup_push( free, buf );
 	
-	// cpy_for_logs_only = *msg;
+	cpy_for_logs_only = *msg;
 	
 	/* 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), goto out );
+		CHECK_FCT_DO( ret = fd_p_sr_store(&peer->p_sr, msg, &hdr->msg_hbhid, bkp_hbh), goto out );
 	}
 	
 	/* Log the message */
-	// fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
+	fd_hook_call(HOOK_MESSAGE_SENT, cpy_for_logs_only, peer, NULL, fd_msg_pmdl_get(cpy_for_logs_only));
 	
 	/* Send the message */
 	CHECK_FCT_DO( ret = fd_cnx_send(cnx, buf, sz, flags), );
@@ -126,7 +127,7 @@
 		pthread_cleanup_push(cleanup_requeue, msg);
 		
 		/* Send the message, log any error */
-		CHECK_FCT_DO( ret = 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),
 			{
 				if (msg) {
 					//fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
@@ -178,7 +179,7 @@
 			cnx = peer->p_cnxctx;
 
 		/* Do send the message */
-		CHECK_FCT_DO( ret = do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
+		CHECK_FCT_DO( ret = do_send(msg, flags, cnx, hbh, peer),
 			{
 				if (msg) {
 					//fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)", strerror(ret) );

--- a/libfdcore/p_psm.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/p_psm.c	Fri May 10 13:26:03 2013 +0200
@@ -335,7 +335,7 @@
 		/* Add a random value between 0 and 4sec */
 		peer->p_psm_timer.tv_sec += random() % 4;
 		peer->p_psm_timer.tv_nsec+= random() % 1000000000L;
-		if (peer->p_psm_timer.tv_nsec > 1000000000L) {
+		if (peer->p_psm_timer.tv_nsec >= 1000000000L) {
 			peer->p_psm_timer.tv_nsec -= 1000000000L;
 			peer->p_psm_timer.tv_sec ++;
 		}
@@ -482,27 +482,32 @@
 	if (event == FDEVP_CNX_MSG_RECV) {
 		struct msg * msg = NULL;
 		struct msg_hdr * hdr;
+		struct fd_cnx_rcvdata rcv_data;
+		struct fd_msg_pmdl * pmdl = NULL;
+		
+		rcv_data.buffer = ev_data;
+		rcv_data.length = ev_sz;
+		pmdl = fd_msg_pmdl_get_inbuf(rcv_data.buffer, rcv_data.length);
 		
 		/* Parse the received buffer */
 		CHECK_FCT_DO( fd_msg_parse_buffer( (void *)&ev_data, ev_sz, &msg), 
 			{
-				fd_log_debug("Received invalid data from peer '%s', closing the connection", peer->p_hdr.info.pi_diamid);
+				fd_hook_call(HOOK_MESSAGE_PARSING_ERROR, NULL, peer, &rcv_data, pmdl );
 				free(ev_data);
 				CHECK_FCT_DO( fd_event_send(peer->p_events, FDEVP_CNX_ERROR, 0, NULL), goto psm_reset );
 				goto psm_loop;
 			} );
 			
+		fd_hook_associate(msg, pmdl);
+	
 		/* If the current state does not allow receiving messages, just drop it */
 		if (cur_state == STATE_CLOSED) {
 			/* In such case, just discard the message */
-			//fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Purged from peer '%s''s queue (CLOSED state).", peer->p_hdr.info.pi_diamid );
+			fd_hook_call(HOOK_MESSAGE_DROPPED, msg, peer, "Message purged from queue, peer in CLOSED state", fd_msg_pmdl_get(msg));
 			fd_msg_free(msg);
 			goto psm_loop;
 		}
 		
-		/* Log incoming message */
-		//fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from '%s' (%s)", ev_sz, peer->p_hdr.info.pi_diamid, STATE_STR(cur_state) );
-	
 		/* Extract the header */
 		CHECK_FCT_DO( fd_msg_hdr(msg, &hdr), goto psm_end );
 		
@@ -512,7 +517,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_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
+				fd_hook_call(HOOK_MESSAGE_DROPPED, msg, peer, "Answer received with no corresponding sent request.", fd_msg_pmdl_get(msg));
 				fd_msg_free(msg);
 				goto psm_loop;
 			}
@@ -520,10 +525,6 @@
 			/* Associate */
 			CHECK_FCT_DO( fd_msg_answ_associate( msg, req ), goto psm_end );
 			
-			/* Display the delay to receive the answer */
-			{
-				//fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %ld.%6.6ld sec.", (long)delay.tv_sec, delay.tv_nsec / 1000 );
-			}
 		} else {
 			/* Mark the incoming request so that we know we have pending answers for this peer */
 			CHECK_POSIX_DO( pthread_mutex_lock(&peer->p_state_mtx), goto psm_end  );
@@ -531,6 +532,9 @@
 			CHECK_POSIX_DO( pthread_mutex_unlock(&peer->p_state_mtx), goto psm_end  );
 		}
 		
+		/* Log incoming message */
+		fd_hook_call(HOOK_MESSAGE_RECEIVED, msg, peer, NULL, fd_msg_pmdl_get(msg));
+		
 		if (cur_state == STATE_OPEN_NEW) {
 			/* OK, we have received something, so the connection is supposedly now in OPEN state at the remote site */
 			fd_psm_change_state(peer, STATE_OPEN );
@@ -568,30 +572,41 @@
 				case STATE_WAITCNXACK_ELEC:
 				case STATE_WAITCEA:
 				case STATE_CLOSED:
-				default:
+				default: {
 					/* In such case, just discard the message */
-					//fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received from peer '%s' while connection was not in state %s.", peer->p_hdr.info.pi_diamid, STATE_STR(cur_state) );
+					char buf[128];
+					snprintf(buf, sizeof(buf), "Received while peer state machine was in state %s.", STATE_STR(cur_state));
+					fd_hook_call(HOOK_MESSAGE_DROPPED, msg, peer, buf, fd_msg_pmdl_get(msg));
 					fd_msg_free(msg);
+				}
 			}
 			goto psm_loop;
 		}
 		
 		/* Link-local message: They must be understood by our dictionary, otherwise we return an error */
 		{
-			int ret = fd_msg_parse_or_error( &msg );
+			struct msg * error = NULL;
+			int ret = fd_msg_parse_or_error( &msg, &error );
 			if (ret != EBADMSG) {
-				CHECK_FCT_DO( ret, goto psm_end );
+				CHECK_FCT_DO( ret, 
+					{ 
+						LOG_E("%s: An unexpected error occurred while parsing a link-local message", peer->p_hdr.info.pi_diamid); 
+						fd_msg_free(msg); 
+						goto psm_end; 
+					} );
 			} else {
-				if (msg) {
+				if (msg == NULL) {
 					/* Send the error back to the peer */
-					CHECK_FCT_DO( ret = fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED),  );
-					if (msg) {
+					CHECK_FCT_DO( ret = fd_out_send(&error, NULL, peer, FD_CNX_ORDERED),  );
+					if (error) {
 						/* 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)", strerror(ret) );
-						CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
+						LOG_E("%s: error sending a message", peer->p_hdr.info.pi_diamid); 
+						CHECK_FCT_DO( fd_msg_free(error), goto psm_end);
 					}
 				} else {
 					/* We received an invalid answer, let's disconnect */
+					LOG_E("%s: Received invalid answer to Base protocol message, disconnecting...", peer->p_hdr.info.pi_diamid);
+					CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
 					CHECK_FCT_DO( fd_event_send(peer->p_events, FDEVP_CNX_ERROR, 0, NULL), goto psm_reset );
 				}
 				goto psm_loop;
@@ -601,7 +616,12 @@
 		/* Handle the LL message and update the expiry timer appropriately */
 		switch (hdr->msg_code) {
 			case CC_CAPABILITIES_EXCHANGE:
-				CHECK_FCT_DO( fd_p_ce_msgrcv(&msg, (hdr->msg_flags & CMD_FLAG_REQUEST), peer), goto psm_reset );
+				CHECK_FCT_DO( fd_p_ce_msgrcv(&msg, (hdr->msg_flags & CMD_FLAG_REQUEST), peer), 
+					{
+						if (msg)
+							CHECK_FCT_DO( fd_msg_free(msg), );
+						goto psm_reset;
+					} );
 				break;
 			
 			case CC_DISCONNECT_PEER:
@@ -670,6 +690,8 @@
 			default:
 				/* Mark the connection problem */
 				peer->p_flags.pf_cnx_pb = 1;
+			
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "The connection was broken", NULL);
 				
 				/* Destroy the connection, restart the timer to a new connection attempt */
 				fd_psm_next_timeout(peer, 1, peer->p_hdr.info.config.pic_tctimer ?: fd_g_config->cnf_timer_tc);
@@ -731,7 +753,6 @@
 			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;
 		}
@@ -752,6 +773,7 @@
 		switch (cur_state) {
 			case STATE_WAITCNXACK_ELEC:
 			case STATE_WAITCNXACK:
+				LOG_D("%s: Connection established", peer->p_hdr.info.pi_diamid);
 				fd_p_ce_handle_newcnx(peer, cnx);
 				break;
 				
@@ -780,6 +802,7 @@
 				break;
 				
 			case STATE_WAITCNXACK:
+				LOG_D("%s: Connection attempt failed", peer->p_hdr.info.pi_diamid);
 				/* Go back to CLOSE */
 				fd_psm_next_timeout(peer, 1, peer->p_hdr.info.config.pic_tctimer ?: fd_g_config->cnf_timer_tc);
 				goto psm_reset;
@@ -802,6 +825,7 @@
 				goto psm_loop;
 				
 			case STATE_CLOSED:
+				LOG_D("%s: Connecting...", peer->p_hdr.info.pi_diamid);
 				CHECK_FCT_DO( fd_psm_change_state(peer, STATE_WAITCNXACK), goto psm_end );
 				fd_psm_next_timeout(peer, 0, CNX_TIMEOUT);
 				CHECK_FCT_DO( fd_p_cnx_init(peer), goto psm_end );
@@ -810,9 +834,10 @@
 			case STATE_SUSPECT:
 				/* Mark the connection problem */
 				peer->p_flags.pf_cnx_pb = 1;
-			case STATE_CLOSING:
 			case STATE_WAITCNXACK:
 			case STATE_WAITCEA:
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, peer, "Timeout while waiting for remote peer", NULL);
+			case STATE_CLOSING:
 				/* Destroy the connection, restart the timer to a new connection attempt */
 				fd_psm_next_timeout(peer, 1, peer->p_hdr.info.config.pic_tctimer ?: fd_g_config->cnf_timer_tc);
 				goto psm_reset;
@@ -848,6 +873,7 @@
 	goto psm_loop;
 	
 psm_end:
+	LOG_N("%s: Going to ZOMBIE state (no more activity)", peer->p_hdr.info.pi_diamid);
 	fd_psm_cleanup(peer, 1);
 	TRACE_DEBUG(INFO, "'%s'\t-> STATE_ZOMBIE (terminated)\t'%s'",
 			STATE_STR(fd_peer_getstate(peer)),

--- a/libfdcore/peers.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/peers.c	Fri May 10 13:26:03 2013 +0200
@@ -490,9 +490,8 @@
 	CHECK_POSIX( pthread_mutex_lock(&cache_avp_lock) );
 	if (!avp_oh_model) {
 		avp_code_t code = AC_ORIGIN_HOST;
-		int ret;
-		CHECK_FCT_DO( ret = fd_dict_search ( fd_g_config->cnf_dict, DICT_AVP, AVP_BY_CODE, &code, &avp_oh_model, ENOENT),
-			{ CHECK_POSIX( pthread_mutex_unlock(&cache_avp_lock) ); return ret; } );
+		CHECK_FCT_DO( fd_dict_search ( fd_g_config->cnf_dict, DICT_AVP, AVP_BY_CODE, &code, &avp_oh_model, ENOENT),
+			{ LOG_E("Cannot find Origin-Host AVP definition in the dictionary!"); (void) pthread_mutex_unlock(&cache_avp_lock); return __ret__; } );
 	}
 	CHECK_POSIX( pthread_mutex_unlock(&cache_avp_lock) );
 	
@@ -503,10 +502,12 @@
 	
 	/* First, check if the Origin-Host value is valid */
 	if (!fd_os_is_valid_DiameterIdentity(avp_hdr->avp_value->os.data, avp_hdr->avp_value->os.len)) {
-		TRACE_DEBUG(INFO, "Received new CER with invalid Origin-Host");
 		CHECK_FCT( fd_msg_new_answer_from_req ( fd_g_config->cnf_dict, cer, MSGFL_ANSW_ERROR ) );
 		CHECK_FCT( fd_msg_rescode_set(*cer, "DIAMETER_INVALID_AVP_VALUE", 
 							"Your Origin-Host contains invalid characters.", avp_oh, 1 ) );
+		
+		fd_hook_call(HOOK_PEER_CONNECT_FAILED, *cer, NULL, "Received CER with invalid Origin-Host AVP", NULL);
+		
 		CHECK_FCT( fd_out_send(cer, *cnx, NULL, FD_CNX_ORDERED) );
 		return EINVAL;
 	}
@@ -545,6 +546,8 @@
 		peer->p_flags.pf_responder = 1;
 		peer->p_flags.pf_delete = 1;
 		
+		LOG_D("Created new peer object for incoming CER: %s", peer->p_hdr.info.pi_diamid);
+		
 #ifndef DISABLE_PEER_EXPIRY
 		/* Set this peer to expire on inactivity */
 		peer->p_hdr.info.config.pic_flags.exp 	= PI_EXP_INACTIVE;
@@ -590,6 +593,10 @@
 		/* Reset the "out" parameters, so that they are not cleanup on function return. */
 		*cer = NULL;
 		*cnx = NULL;
+	} else {
+		char buf[1024];
+		snprintf(buf, sizeof(buf), "An error occurred while processing new incoming CER: %s", strerror(ret));
+		fd_hook_call(HOOK_PEER_CONNECT_FAILED, *cer, NULL, buf, NULL);
 	}
 	
 	return ret;

--- a/libfdcore/routing_dispatch.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/routing_dispatch.c	Fri May 10 13:26:03 2013 +0200
@@ -431,7 +431,7 @@
 	enum disp_action action;
 	char * ec = NULL;
 	char * em = NULL;
-	struct msg *msgptr = msg;
+	struct msg *msgptr = msg, *error = NULL;
 
 	/* Read the message header */
 	CHECK_FCT( fd_msg_hdr(msg, &hdr) );
@@ -441,19 +441,27 @@
 	  (draft-asveren-dime-dupcons-00). This may conflict with path validation decisions, no clear answer yet */
 
 	/* At this point, we need to understand the message content, so parse it */
-	CHECK_FCT_DO( ret = fd_msg_parse_or_error( &msgptr ),
+	CHECK_FCT_DO( fd_msg_parse_or_error( &msgptr, &error ),
 		{
-			/* in case of error */
-			if ((ret == EBADMSG) && (msgptr != NULL)) {
-				/* msgptr now contains the answer message to send back */
-				CHECK_FCT( fd_fifo_post(fd_g_outgoing, &msgptr) );
+			int rescue = 0;
+			if (__ret__ != EBADMSG) {
+				fd_hook_call(HOOK_MESSAGE_DROPPED, msgptr, NULL, "Error while parsing received answer", fd_msg_pmdl_get(msgptr));
+				fd_msg_free(msgptr);
+			} else {
+				if (!msgptr) {
+					/* error now contains the answer message to send back */
+					CHECK_FCT( fd_fifo_post(fd_g_outgoing, &error) );
+				} else if (!error) {
+					/* We have received an invalid answer to our query */
+					fd_hook_call(HOOK_MESSAGE_DROPPED, msgptr, NULL, "Received answer failed the dictionary / rules parsing", fd_msg_pmdl_get(msgptr));
+					fd_msg_free(msgptr);
+				} else {
+					/* We will pass the invalid received error to the application */
+					rescue = 1;
+				}
 			}
-			if (msgptr) {	/* another error happen'd */
-				//fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
-				CHECK_FCT_DO( fd_msg_free(msgptr), /* continue */);
-			}
-			/* We're done with this one */
-			return 0;
+			if (!rescue)
+				return 0; /* We are done with this message, go to the next */
 		} );
 
 	/* First, if the original request was registered with a callback and we receive the answer, call it. */

--- a/libfdcore/server.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdcore/server.c	Fri May 10 13:26:03 2013 +0200
@@ -133,10 +133,11 @@
 {
 	struct client * c = arg;
 	struct server * s = NULL;
-	uint8_t       * buf = NULL;
-	size_t 		bufsz;
+	struct fd_cnx_rcvdata rcv_data;
+	struct fd_msg_pmdl * pmdl = NULL;
 	struct msg    * msg = NULL;
 	struct msg_hdr *hdr = NULL;
+	struct fd_pei pei;
 	
 	TRACE_ENTRY("%p", c);
 	
@@ -151,9 +152,11 @@
 	if (s->secur) {
 		int ret = fd_cnx_handshake(c->conn, GNUTLS_SERVER, NULL, NULL);
 		if (ret != 0) {
-			if (TRACE_BOOL(INFO)) {
-				fd_log_debug("TLS handshake failed for client '%s', connection aborted.", fd_cnx_getid(c->conn));
-			}
+			char buf[1024];
+			snprintf(buf, sizeof(buf), "TLS handshake failed for client '%s', connection aborted.", fd_cnx_getid(c->conn));
+			
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, NULL, buf, NULL);
+			
 			goto cleanup;
 		}
 	} else {
@@ -165,23 +168,65 @@
 	c->ts.tv_sec += INCNX_TIMEOUT;
 	
 	/* Receive the first Diameter message on the connection -- cleanup in case of timeout */
-	CHECK_FCT_DO( fd_cnx_receive(c->conn, &c->ts, &buf, &bufsz), goto cleanup );
+	CHECK_FCT_DO( fd_cnx_receive(c->conn, &c->ts, &rcv_data.buffer, &rcv_data.length), 
+		{
+			char buf[1024];
+			
+			switch (__ret__) {
+			case ETIMEDOUT:
+				snprintf(buf, sizeof(buf), "Client '%s' did not send CER within %ds, connection aborted.", fd_cnx_getid(c->conn), INCNX_TIMEOUT);
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, NULL, buf, NULL);
+				break;
+			
+			case ENOTCONN:
+				snprintf(buf, sizeof(buf), "Connection from '%s' in error before CER was received.", fd_cnx_getid(c->conn));
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, NULL, buf, NULL);
+				break;
+			
+			default:
+				snprintf(buf, sizeof(buf), "Connection from '%s': unspecified error, connection aborted.", fd_cnx_getid(c->conn));
+				fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, NULL, buf, NULL);
+			}
+			goto cleanup;
+		} );
 	
-	TRACE_DEBUG(FULL, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn));
+	TRACE_DEBUG(FULL, "Received %zdb from new client '%s'", rcv_data.length, fd_cnx_getid(c->conn));
+	
+	pmdl = fd_msg_pmdl_get_inbuf(rcv_data.buffer, rcv_data.length);
 	
 	/* Try parsing this message */
-	CHECK_FCT_DO( fd_msg_parse_buffer( &buf, bufsz, &msg ), /* Parsing failed */ goto cleanup );
+	CHECK_FCT_DO( fd_msg_parse_buffer( &rcv_data.buffer, rcv_data.length, &msg ), 
+		{ 	/* Parsing failed */ 
+			fd_hook_call(HOOK_MESSAGE_PARSING_ERROR, NULL, NULL, &rcv_data, pmdl );
+			goto cleanup;
+		} );
 	
 	/* Log incoming message */
-	//fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn) );
+	fd_hook_associate(msg, pmdl);
+	fd_hook_call(HOOK_MESSAGE_RECEIVED, msg, NULL, fd_cnx_getid(c->conn), fd_msg_pmdl_get(msg));
 	
 	/* 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 );
+	CHECK_FCT_DO( fd_msg_parse_rules( msg, fd_g_config->cnf_dict, &pei ), 
+		{ /* Parsing failed -- trace details */ 
+			char buf[1024];
+			
+			fd_hook_call(HOOK_MESSAGE_PARSING_ERROR, msg, NULL, pei.pei_message ?: pei.pei_errcode, fd_msg_pmdl_get(msg));
+			
+			snprintf(buf, sizeof(buf), "Error parsing CER from '%s', connection aborted.", fd_cnx_getid(c->conn));
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, NULL, NULL, buf, NULL);
+			
+			goto cleanup;
+		} );
 	
 	/* 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),
-		{ fd_log_debug("Connection '%s', expecting CER, received something else, closing...", fd_cnx_getid(c->conn)); goto cleanup; } );
+		{ /* Parsing failed -- trace details */ 
+			char buf[1024];
+			snprintf(buf, sizeof(buf), "Expected CER from '%s', received a different message, connection aborted.", fd_cnx_getid(c->conn));
+			fd_hook_call(HOOK_PEER_CONNECT_FAILED, msg, NULL, buf, NULL);
+			goto cleanup;
+		} );
 	
 	/* Finally, pass the information to the peers module which will handle it next */
 	pthread_cleanup_push((void *)fd_cnx_destroy, c->conn);
@@ -199,7 +244,6 @@
 	
 	/* 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 */);
 	}
 	
@@ -208,7 +252,7 @@
 		fd_cnx_destroy(c->conn);
 	
 	/* Cleanup the received buffer if any */
-	free(buf);
+	free(rcv_data.buffer);
 	
 	/* Detach the thread, cleanup the client structure */
 	pthread_detach(pthread_self());
@@ -239,8 +283,6 @@
 		/* Wait for a new client or cancel */
 		CHECK_MALLOC_DO( conn = fd_cnx_serv_accept(s->conn), goto error );
 		
-		TRACE_DEBUG(FULL, "New connection accepted");
-		
 		/* Create a client structure */
 		CHECK_MALLOC_DO( c = malloc(sizeof(struct client)), goto error );
 		memset(c, 0, sizeof(struct client));
@@ -260,8 +302,9 @@
 error:	
 	if (s)
 		set_status(s, TERMINATED);
-	/* Send error signal to the daemon */
-	TRACE_DEBUG(INFO, "An error occurred in server module! Thread is terminating...");
+
+	/* Send error signal to the core */
+	LOG_F( "An error occurred in server module! Thread is terminating...");
 	CHECK_FCT_DO(fd_event_send(fd_g_config->cnf_main_ev, FDEV_TERMINATE, 0, NULL), );
 
 	return NULL;

--- a/libfdproto/fifo.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdproto/fifo.c	Fri May 10 13:26:03 2013 +0200
@@ -411,6 +411,7 @@
 	/* Create a new list item */
 	CHECK_MALLOC_DO(  new = malloc (sizeof (struct fifo_item)) , {
 			pthread_mutex_unlock( &queue->mtx );
+			return ENOMEM;
 		} );
 	
 	fd_list_init(&new->item, *item);
@@ -469,11 +470,11 @@
 	
 	ASSERT( ! FD_IS_LIST_EMPTY(&queue->list) );
 	
-	fi = (struct fifo_item *)queue->list.next;
+	fi = (struct fifo_item *)(queue->list.next);
+	ret = fi->item.o;
 	fd_list_unlink(&fi->item);
 	queue->count--;
 	queue->total_items++;
-	ret = fi->item.o;
 	
 	/* Update the timings */
 	CHECK_SYS_DO(  clock_gettime(CLOCK_REALTIME, &now), goto skip_timing  );
@@ -577,8 +578,8 @@
 /* The internal function for fd_fifo_timedget and fd_fifo_get */
 static int fifo_tget ( struct fifo * queue, void ** item, int istimed, const struct timespec *abstime)
 {
-	int timedout = 0;
 	int call_cb = 0;
+	int ret = 0;
 	
 	/* Check the parameters */
 	CHECK_PARAMS( CHECK_FIFO( queue ) && item && (abstime || !istimed) );
@@ -597,13 +598,12 @@
 		TRACE_DEBUG(FULL, "The queue is being destroyed -> EPIPE");
 		return EPIPE;
 	}
-		
+	
 	if (queue->count > 0) {
 		/* There are items in the queue, so pick the first one */
 		*item = mq_pop(queue);
 		call_cb = test_l_cb(queue);
 	} else {
-		int ret = 0;
 		/* We have to wait for a new item */
 		queue->thrs++ ;
 		pthread_cleanup_push( fifo_cleanup, queue);
@@ -617,12 +617,7 @@
 		if (ret == 0)
 			goto awaken;  /* test for spurious wake-ups */
 		
-		if (istimed && (ret == ETIMEDOUT)) {
-			timedout = 1;
-		} else {
-			/* Unexpected error condition (means we need to debug) */
-			ASSERT( ret == 0 /* never true */ );
-		}
+		/* otherwise (ETIMEDOUT / other error) just continue */
 	}
 	
 	/* Unlock */
@@ -633,7 +628,7 @@
 		(*queue->l_cb)(queue, &queue->data);
 	
 	/* Done */
-	return timedout ? ETIMEDOUT : 0;
+	return ret;
 }
 
 /* Get the next available item, block until there is one */

--- a/libfdproto/messages.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdproto/messages.c	Fri May 10 13:26:03 2013 +0200
@@ -201,6 +201,9 @@
 	memset(msg, 0, sizeof(struct msg));
 	init_chain( &msg->msg_chain, MSG_MSG);
 	msg->msg_eyec = MSG_MSG_EYEC;
+	
+	fd_list_init(&msg->msg_pmdl.sentinel, NULL);
+	CHECK_POSIX_DO( pthread_mutex_init(&msg->msg_pmdl.lock, NULL), );
 }
 
 
@@ -1951,23 +1954,20 @@
 	
 	CHECK_PARAMS(  buffer &&  *buffer  &&  msg  &&  (buflen >= GETMSGHDRSZ())  );
 	buf = *buffer;
-	*buffer = NULL;
 	
 	if ( buf[0] != DIAMETER_VERSION) {
 		TRACE_DEBUG(INFO, "Invalid version in message: %d (supported: %d)", buf[0], DIAMETER_VERSION);
-		free(buf);
 		return EBADMSG;
 	}
 	
 	msglen = ntohl(*(uint32_t *)buf) & 0x00ffffff;
 	if ( buflen < msglen ) {  
 		TRACE_DEBUG(INFO, "Truncated message (%zd / %d)", buflen, msglen );
-		free(buf);
 		return EBADMSG; 
 	}
 	
 	/* Create a new object */
-	CHECK_MALLOC_DO( new = malloc (sizeof(struct msg)),  { free(buf); return ENOMEM; }  );
+	CHECK_MALLOC( new = malloc (sizeof(struct msg)) );
 	
 	/* Initialize the fields */
 	init_msg(new);
@@ -1983,11 +1983,12 @@
 	new->msg_public.msg_hbhid = ntohl(*(uint32_t *)(buf+12));
 	new->msg_public.msg_eteid = ntohl(*(uint32_t *)(buf+16));
 	
-	new->msg_rawbuffer = buf;
-	
 	/* Parse the AVP list */
 	CHECK_FCT_DO( ret = parsebuf_list(buf + GETMSGHDRSZ(), buflen - GETMSGHDRSZ(), &new->msg_chain.children), { destroy_tree(_C(new)); return ret; }  );
 	
+	/* Parsing successful */
+	new->msg_rawbuffer = buf;
+	*buffer = NULL;
 	*msg = new;
 	return 0;
 }

--- a/libfdproto/utils.c	Fri May 10 13:24:23 2013 +0200
+++ b/libfdproto/utils.c	Fri May 10 13:26:03 2013 +0200
@@ -65,10 +65,28 @@
 		if (rc) {
 			CHECK_MALLOC_DO( fd_dump_extend( FD_DUMP_STD_PARAMS, "%s", gai_strerror(rc)), return NULL);
 		} else {
-			CHECK_MALLOC_DO( fd_dump_extend( FD_DUMP_STD_PARAMS, "%s", &addrbuf[0]), return NULL);
+			CHECK_MALLOC_DO( fd_dump_extend( FD_DUMP_STD_PARAMS, "%s(s)", &addrbuf[0], &servbuf[0]), return NULL);
 		}
 	} else {
 		CHECK_MALLOC_DO( fd_dump_extend( FD_DUMP_STD_PARAMS, "(NULL / ANY)"), return NULL);
 	}
 	return *buf;
 }
+
+void fd_sa_sdump_numeric(char * buf /* must be at least sSA_DUMP_STRLEN */, sSA * sa)
+{
+	char addrbuf[INET6_ADDRSTRLEN];
+	char servbuf[32];
+	
+	if (sa) {
+		int rc = getnameinfo(sa, sSAlen( sa ), addrbuf, sizeof(addrbuf), servbuf, sizeof(servbuf), NI_NUMERICHOST | NI_NUMERICSERV);
+		if (rc) {
+			snprintf(buf, sSA_DUMP_STRLEN, "%s", gai_strerror(rc));
+		} else {
+			snprintf(buf, sSA_DUMP_STRLEN, "%s(%s)", addrbuf, servbuf);
+		}
+	} else {
+		snprintf(buf, sSA_DUMP_STRLEN, "(NULL / ANY)");
+	}
+	
+}

--- a/tests/testmesg.c	Fri May 10 13:24:23 2013 +0200
+++ b/tests/testmesg.c	Fri May 10 13:26:03 2013 +0200
@@ -756,6 +756,7 @@
 			
 			{
 				unsigned char * buftmp = NULL;
+				struct msg * error;
 				/* Check the parse or error works as expected */
 				CPYBUF();
 				
@@ -764,7 +765,9 @@
 				/* Check that we cannot support this message now */
 				CHECK( 0, fd_msg_init() );
 				CHECK( 0, fd_msg_parse_buffer( &buf_cpy, 344, &msg) );
-				CHECK( EBADMSG, fd_msg_parse_or_error( &msg ) );
+				CHECK( EBADMSG, fd_msg_parse_or_error( &msg, &error ) );
+				CHECK( NULL, msg );
+				msg = error;
 				
 				CHECK( 0, fd_msg_bufferize( msg, &buftmp, NULL ) );				
 				

--- a/tests/tests.h	Fri May 10 13:24:23 2013 +0200
+++ b/tests/tests.h	Fri May 10 13:26:03 2013 +0200
@@ -205,6 +205,8 @@
 	
 	CHECK( 0, fd_libproto_init() );
 	
+	CHECK( 0, fd_hooks_init() );	
+	
 	fd_log_threadname(fname);
 	
 	/* Parse the command line */