Changeset 1103:d8591b1c56cd in freeDiameter

Timestamp:

May 10, 2013, 7:48:57 PM (11 years ago)

Author:

Sebastien Decugis <sdecugis@freediameter.net>

Branch:

default

Phase:

public

Message:

Implemented a few hooks

Files:

• extensions/CMakeLists.txt (modified) (1 diff)
• extensions/dbg_msg_timings/CMakeLists.txt (added)
• extensions/dbg_msg_timings/dbg_msg_timings.c (added)
• include/freeDiameter/libfdcore.h (modified) (8 diffs)
• include/freeDiameter/libfdproto.h (modified) (2 diffs)
• libfdcore/cnxctx.c (modified) (15 diffs)
• libfdcore/hooks.c (modified) (4 diffs)
• libfdcore/messages.c (modified) (5 diffs)
• libfdcore/p_ce.c (modified) (15 diffs)
• libfdcore/p_cnx.c (modified) (3 diffs)
• libfdcore/p_out.c (modified) (6 diffs)
• libfdcore/p_psm.c (modified) (15 diffs)
• libfdcore/peers.c (modified) (4 diffs)
• libfdcore/routing_dispatch.c (modified) (2 diffs)
• libfdcore/server.c (modified) (7 diffs)
• libfdproto/fifo.c (modified) (3 diffs)
• libfdproto/messages.c (modified) (4 diffs)
• libfdproto/utils.c (modified) (2 diffs)
• tests/testmesg.c (modified) (2 diffs)
• tests/tests.h (modified) (1 diff)

extensions/CMakeLists.txt

@@ -86 +86 @@
 
 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)

include/freeDiameter/libfdcore.h

@@ -553 +553 @@
 
 
-/* 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 );
 
 
@@ -926 +931 @@
                  - {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.
                  */
@@ -959 +964 @@
                  */
         
+        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.
@@ -994 +1005 @@
                    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).
@@ -1000 +1011 @@
         
         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).
@@ -1008 +1019 @@
         
         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.
@@ -1069 +1081 @@
  *
  * 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.
@@ -1093 +1105 @@
 /* Remove a hook registration */
 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);
 
 

include/freeDiameter/libfdproto.h

@@ -146 +146 @@
  */
 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, 
@@ -609 +611 @@
 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);
 
 

libfdcore/cnxctx.c

@@ -228 +228 @@
         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;
@@ -264 +258 @@
                         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
@@ -275 +271 @@
                         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 */
@@ -287 +283 @@
         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 */
@@ -295 +294 @@
                 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);
         }
         
@@ -329 +311 @@
         /* 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 */
@@ -347 +320 @@
                         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;
@@ -362 +337 @@
         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;
                 }
@@ -403 +370 @@
                 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 */
@@ -429 +383 @@
                         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;
@@ -678 +634 @@
 size_t fd_msg_pmdl_sizewithoverhead(size_t datalen)
 {
-        return PMDL_PADDED(datalen);
+        return PMDL_PADDED(datalen) + sizeof(struct fd_msg_pmdl);
 }
 
@@ -698 +654 @@
         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;
@@ -707 +663 @@
         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;
@@ -762 +718 @@
                    || (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 */
@@ -1004 +960 @@
                    || (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;

libfdcore/hooks.c

@@ -186 +186 @@
         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), );
@@ -201 +200 @@
         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 */
@@ -231 +235 @@
 }
 
+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 */
@@ -237 +268 @@
         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);
-                }
-                
-                /* Now, call this callback */
-                (*h->fd_hook_cb)(type, msg, &peer->p_hdr, other, pmd, h->regdata);
+        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);
+                }
         }
         
         /* 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);
+        }
+}

libfdcore/messages.c

@@ -346 +346 @@
 
 /* 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;
@@ -355 +355 @@
         TRACE_ENTRY("%p", msg);
         
-        CHECK_PARAMS(msg && *msg);
+        CHECK_PARAMS(msg && *msg && error);
         m = *msg;
+        *error = NULL;
         
         /* Parse the message against our dictionary */
@@ -364 +365 @@
                 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) );
@@ -373 +374 @@
                 
                 /* 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 {
@@ -409 +413 @@
                                         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;
         }
         

libfdcore/p_ce.c

@@ -671 +671 @@
                         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) );
@@ -678 +680 @@
                         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 */
@@ -720 +724 @@
         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;
@@ -731 +739 @@
         
         /* 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;
@@ -745 +760 @@
                 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);
@@ -757 +772 @@
                 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 */
@@ -778 +794 @@
                                 {
                                         /* 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;
                                 } );
@@ -818 +834 @@
         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;
@@ -928 +948 @@
         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 ) );
         
@@ -936 +960 @@
                         {
                                 /* 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 */
@@ -948 +978 @@
                         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;
@@ -982 +1012 @@
         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);
         }
@@ -1027 +1061 @@
                                 
                                 /* 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);
                                 
@@ -1041 +1076 @@
                                 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);
                         }
@@ -1048 +1084 @@
                         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);
         }

libfdcore/p_cnx.c

@@ -236 +236 @@
                         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;
@@ -279 +280 @@
                         {
                                 /* 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);
@@ -285 +286 @@
                                 goto out_pop;
                         } );
+                LOG_A("%s: TLS handshake successful.", peer->p_hdr.info.pi_diamid);
         } else {
                 /* Prepare to receive the next message */

libfdcore/p_out.c

@@ -37 +37 @@
 
 /* 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;
@@ -45 +45 @@
         int ret;
         uint32_t bkp_hbh = 0;
-        
-        TRACE_ENTRY("%p %x %p %p %p", msg, flags, cnx, hbh, srl);
+        struct msg *cpy_for_logs_only;
+        
+        TRACE_ENTRY("%p %x %p %p %p", msg, flags, cnx, hbh, peer);
         
         /* Retrieve the message header */
@@ -53 +54 @@
         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;
@@ -64 +65 @@
         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 */
@@ -127 +128 @@
                 
                 /* 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) {
@@ -179 +180 @@
 
                 /* 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) {

libfdcore/p_psm.c

@@ -483 +483 @@
                 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 );
@@ -493 +499 @@
                         } );
                         
+                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 );
@@ -513 +518 @@
                         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;
@@ -521 +526 @@
                         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 */
@@ -531 +532 @@
                         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) {
@@ -569 +573 @@
                                 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;
@@ -579 +586 @@
                 /* 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 );
                                 }
@@ -602 +617 @@
                 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;
                         
@@ -671 +691 @@
                                 /* 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 */
@@ -732 +754 @@
                 }
                 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;
@@ -753 +774 @@
                         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;
@@ -781 +803 @@
                                 
                         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);
@@ -803 +826 @@
                                 
                         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);
@@ -811 +835 @@
                                 /* 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);
@@ -849 +874 @@
         
 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'",

libfdcore/peers.c

@@ -491 +491 @@
         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) );
@@ -504 +503 @@
         /* 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 +546 @@
                 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
@@ -591 +594 @@
                 *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);
         }
         

libfdcore/routing_dispatch.c

@@ -432 +432 @@
         char * ec = NULL;
         char * em = NULL;
-        struct msg *msgptr = msg;
+        struct msg *msgptr = msg, *error = NULL;
 
         /* Read the message header */
@@ -442 +442 @@
 
         /* 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) );
-                        }
-                        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;
+                        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 (!rescue)
+                                return 0; /* We are done with this message, go to the next */
                 } );
 

libfdcore/server.c

@@ -134 +134 @@
         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);
@@ -152 +153 @@
                 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;
                 }
@@ -166 +169 @@
         
         /* 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 );
-        
-        TRACE_DEBUG(FULL, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn));
+        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'", 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 */
@@ -200 +245 @@
         /* 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 */);
         }
@@ -209 +253 @@
         
         /* Cleanup the received buffer if any */
-        free(buf);
+        free(rcv_data.buffer);
         
         /* Detach the thread, cleanup the client structure */
@@ -239 +283 @@
                 /* 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 */
@@ -261 +303 @@
         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), );
 

libfdproto/fifo.c

@@ -412 +412 @@
         CHECK_MALLOC_DO(  new = malloc (sizeof (struct fifo_item)) , {
                         pthread_mutex_unlock( &queue->mtx );
+                        return ENOMEM;
                 } );
         
@@ -470 +471 @@
         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 */
@@ -598 +599 @@
                 return EPIPE;
         }
-                
+        
         if (queue->count > 0) {
                 /* There are items in the queue, so pick the first one */

libfdproto/messages.c

@@ -202 +202 @@
         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), );
 }
 
@@ -1952 +1955 @@
         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;
         }
@@ -1963 +1964 @@
         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 */
@@ -1984 +1984 @@
         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;

libfdproto/utils.c

@@ -66 +66 @@
                         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 {
@@ -73 +73 @@
         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)");
+        }
+        
+}

tests/testmesg.c

@@ -757 +757 @@
                         {
                                 unsigned char * buftmp = NULL;
+                                struct msg * error;
                                 /* Check the parse or error works as expected */
                                 CPYBUF();
@@ -765 +766 @@
                                 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 ) );                             

tests/tests.h

@@ -206 +206 @@
         CHECK( 0, fd_libproto_init() );
         
+        CHECK( 0, fd_hooks_init() );    
+        
         fd_log_threadname(fname);