# HG changeset patch # User Thomas Klausner # Date 1368185163 -7200 # Node ID 8401adfb58f5671e0e3cbad0a0f4bd63e50b8fa4 # Parent 6b4a417d2845a172df52cede00bb5a9cecb16113# Parent 757df62cadb602529ec7ae9e05f9e33782661699 merge diff -r 6b4a417d2845 -r 8401adfb58f5 extensions/CMakeLists.txt --- 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) diff -r 6b4a417d2845 -r 8401adfb58f5 extensions/dbg_msg_timings/CMakeLists.txt --- /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) + diff -r 6b4a417d2845 -r 8401adfb58f5 extensions/dbg_msg_timings/dbg_msg_timings.c --- /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 * +* * +* 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 + +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); diff -r 6b4a417d2845 -r 8401adfb58f5 include/freeDiameter/libfdcore.h --- 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); + + /*============================================================*/ /* diff -r 6b4a417d2845 -r 8401adfb58f5 include/freeDiameter/libfdproto.h --- 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) */ diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/cnxctx.c --- 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 */ || (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 */ || (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; } diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/hooks.c --- 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 : "", 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 : "", 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 : "", 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)""; + + if (!id) + id = (DiamId_t)""; + + 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 : "", 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)""; + + if (!id) + id = (DiamId_t)""; + + 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 : "", (char *)other, buf); + } else { + LOG_D("Connection to '%s' failed: %s", peer ? peer->p_hdr.info.pi_diamid : "", (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 : "", buf); + break; + } + + } + + free(buf); + } } diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/messages.c --- 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 */ diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/p_ce.c --- 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); } diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/p_cnx.c --- 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 ); diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/p_out.c --- 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) ); diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/p_psm.c --- 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)), diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/peers.c --- 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; diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/routing_dispatch.c --- 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. */ diff -r 6b4a417d2845 -r 8401adfb58f5 libfdcore/server.c --- 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; diff -r 6b4a417d2845 -r 8401adfb58f5 libfdproto/fifo.c --- 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 */ diff -r 6b4a417d2845 -r 8401adfb58f5 libfdproto/messages.c --- 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; } diff -r 6b4a417d2845 -r 8401adfb58f5 libfdproto/utils.c --- 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)"); + } + +} diff -r 6b4a417d2845 -r 8401adfb58f5 tests/testmesg.c --- 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 ) ); diff -r 6b4a417d2845 -r 8401adfb58f5 tests/tests.h --- 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 */