Navigation

Changes in / [1082:b380c9f3be1e:1077:b36c81e52e9a] in freeDiameter


Ignore:
Files:
1 added
1 deleted
20 edited

Legend:

Unmodified
Added
Removed

  • doc/dbg_interactive.py.sample

    r1078 r979  
    364364a_msg = msg()
    365365a_msg.dump()
     366a_msg.log(FD_MSG_LOG_DROPPED, "Check libfdproto for more details. Configure with fd_msg_log_config.")
    366367del a_msg
    367368

  • extensions/dbg_interactive/messages.i

    r1078 r1014  
    297297        }
    298298       
     299        /* Log to file (depending on config)  */
     300        void log ( enum fd_msg_log_cause cause, char * message ) {
     301                fd_msg_log( cause, $self, message );
     302        }
     303       
    299304        /* Model */
    300305        struct dict_object * model() {

  • freeDiameterd/main.c

    r1081 r931  
    4949static char *conffile = NULL;
    5050static int gnutls_debug = 0;
     51static int fd_msg_log_enabled = 0; /* all logs disabled by default, this field is a bitfield of enabled FD_MSG_LOG_* */
    5152
    5253/* gnutls debug */
    … …  
    8788        }
    8889       
     90        /* set messages logging */
     91        if (fd_msg_log_enabled) {
     92                if (fd_msg_log_enabled & (1 << FD_MSG_LOG_DROPPED)) {
     93                        CHECK_FCT( fd_msg_log_config(FD_MSG_LOG_DROPPED, FD_MSG_LOGTO_DEBUGONLY, NULL) );
     94                }
     95                if (fd_msg_log_enabled & (1 << FD_MSG_LOG_RECEIVED)) {
     96                        CHECK_FCT( fd_msg_log_config(FD_MSG_LOG_RECEIVED, FD_MSG_LOGTO_DEBUGONLY, NULL) );
     97                }
     98                if (fd_msg_log_enabled & (1 << FD_MSG_LOG_SENT)) {
     99                        CHECK_FCT( fd_msg_log_config(FD_MSG_LOG_SENT, FD_MSG_LOGTO_DEBUGONLY, NULL) );
     100                }
     101                if (fd_msg_log_enabled & (1 << FD_MSG_LOG_NODELIVER)) {
     102                        CHECK_FCT( fd_msg_log_config(FD_MSG_LOG_NODELIVER, FD_MSG_LOGTO_DEBUGONLY, NULL) );
     103                }
     104                if (fd_msg_log_enabled & (1 << FD_MSG_LOG_TIMING)) {
     105                        CHECK_FCT( fd_msg_log_config(FD_MSG_LOG_TIMING, FD_MSG_LOGTO_DEBUGONLY, NULL) );
     106                }
     107        }
     108               
    89109        /* Allow SIGINT and SIGTERM from this point to terminate the application */
    90110        CHECK_POSIX( pthread_create(&signals_thr, NULL, catch_signals, NULL) );
    … …  
    149169                "  -V, --version          Print version and exit\n"
    150170                "  -c, --config=filename  Read configuration from this file instead of the \n"
    151                 "                           default location (" DEFAULT_CONF_PATH "/" FD_DEFAULT_CONF_FILENAME ").\n");
     171                "                           default location (" DEFAULT_CONF_PATH "/" FD_DEFAULT_CONF_FILENAME ").\n"
     172                "  -M, --enable_msg_log=( DROPPED | RECEIVED | SENT | NODELIVER | TIMING )\n"
     173                "                         Enable logging of these messages in the output.\n");
    152174        printf( "\nDebug:\n"
    153175                "  These options are mostly useful for developers\n"
    154176                "  -l, --dbglocale        Set the locale for error messages\n"
    155                 "  -d, --debug            Increase verbosity of debug messages if default logger is used\n"
    156                 "  -q, --quiet            Decrease verbosity if default logger is used\n"
     177                "  -d, --debug            Increase verbosity of debug messages\n"
     178                "  -q, --quiet            Decrease verbosity then remove debug messages\n"
    157179                "  --dbg_gnutls <int>     Enable GNU TLS debug at level <int>\n");
    158180}
    … …  
    175197                { "dbg_file",   required_argument,      NULL, 'F' },
    176198                { "dbg_gnutls", required_argument,      NULL, 'g' },
     199                { "enable_msg_log",     optional_argument,      NULL, 'M' },
    177200                { NULL,         0,                      NULL, 0 }
    178201        };
    … …  
    209232                                break;
    210233                               
     234                        case 'M':       /* disable logging of these messages */
     235                                if (optarg) {
     236                                        if (!strcmp(optarg, "DROPPED")) {
     237                                                fd_msg_log_enabled |= 1 << FD_MSG_LOG_DROPPED;
     238                                        } else
     239                                        if (!strcmp(optarg, "RECEIVED")) {
     240                                                fd_msg_log_enabled |= 1 << FD_MSG_LOG_RECEIVED;
     241                                        } else
     242                                        if (!strcmp(optarg, "SENT")) {
     243                                                fd_msg_log_enabled |= 1 << FD_MSG_LOG_SENT;
     244                                        } else
     245                                        if (!strcmp(optarg, "NODELIVER")) {
     246                                                fd_msg_log_enabled |= 1 << FD_MSG_LOG_NODELIVER;
     247                                        } else
     248                                        if (!strcmp(optarg, "TIMING")) {
     249                                                fd_msg_log_enabled |= 1 << FD_MSG_LOG_TIMING;
     250                                        } else {
     251                                                main_help();
     252                                                exit(0);
     253                                        }
     254                                } else {
     255                                        fd_msg_log_enabled = -1; /* all logs enabled */
     256                                }
     257
    211258                        case 'd':       /* Increase verbosity of debug messages.  */
    212259                                fd_g_debug_lvl++;

  • include/freeDiameter/libfdproto.h

    r1082 r1071  
    23402340void fd_msg_dump_walk ( int level, msg_or_avp *obj );
    23412341void fd_msg_dump_one  ( int level, msg_or_avp *obj );
    2342 
    2343 /* Helper functions to get a dump of an object in the logs. Several formats are available.
    2344  *  buf   : a buffer that can be reallocated if needed. *buf==NULL is also accepted for first allocation
    2345  *  buflen: the length of the buffer buf.
    2346  *  dict  : optional, the dictionary to use for resolving objects, if force_parsing != 0
    2347  *  obj   : the message or AVP to dump.
    2348  *
    2349  * After use, the buf pointer should be freed.
    2350  */
    2351 /* one-line dump with only short information */
    2352 void fd_msg_dump_summary( char ** buf, size_t buflen, struct dictionary *dict, msg_or_avp *obj, int force_parsing);
    2353 /* one-line dump with all the contents of the message */
    2354 void fd_msg_dump_full( char ** buf, size_t buflen, struct dictionary *dict, msg_or_avp *obj, int force_parsing);
    2355 /* multi-line human-readable dump similar to wireshark output */
    2356 void fd_msg_dump_treeview( char ** buf, size_t buflen, struct dictionary *dict, msg_or_avp *obj, int force_parsing);
    2357 
     2342/* Dump full message to log */
     2343void fd_msg_dump_full ( int level, struct dictionary *dict, const char *prefix, msg_or_avp *obj );
     2344
     2345/*
     2346 * FUNCTION:    fd_msg_log
     2347 *
     2348 * PARAMETERS:
     2349 *  cause        : Context for calling this function. This allows the log facility to be configured precisely.
     2350 *  msg          : The message to log.
     2351 *  prefix_format: Printf-style format message that is printed ahead of the message. Might be reason for drop or so.
     2352 *
     2353 * DESCRIPTION:
     2354 *   This function is called when a Diameter message reaches some particular points in the fD framework.
     2355 * The actual effect is configurable: log in a separate file, dump in the debug log, etc.
     2356 *
     2357 * RETURN VALUE:
     2358 *   -
     2359 */
     2360enum fd_msg_log_cause {
     2361        FD_MSG_LOG_DROPPED = 1,  /* message has been dropped by the framework */
     2362        FD_MSG_LOG_RECEIVED,     /* message received from the network */
     2363        FD_MSG_LOG_SENT,         /* message sent to another peer */
     2364        FD_MSG_LOG_NODELIVER,    /* message could not be delivered to any peer */
     2365        FD_MSG_LOG_TIMING        /* profiling messages */
     2366};
     2367#define FD_MSG_LOG_MAX FD_MSG_LOG_TIMING
     2368void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... ) _ATTRIBUTE_PRINTFLIKE_(3,4);
     2369
     2370/* configure the msg_log facility */
     2371enum fd_msg_log_method {
     2372        FD_MSG_LOGTO_NONE = 0, /* The message is not dumped. This is the default. */
     2373        FD_MSG_LOGTO_DEBUGONLY, /* Simply log the message with other debug information, at the INFO level. */
     2374        FD_MSG_LOGTO_FILE,    /* Messages are dumped in a single file, defined in arg */
     2375        FD_MSG_LOGTO_DIR    /* Messages are dumped in different files within one directory defined in arg. */
     2376};
     2377int fd_msg_log_config(enum fd_msg_log_cause cause, enum fd_msg_log_method method, const char * arg);
     2378void fd_msg_log_init(struct dictionary *dict);
    23582379
    23592380/*********************************************/
    … …  
    25072528int fd_msg_source_set( struct msg * msg, DiamId_t diamid, size_t diamidlen, int add_rr, struct dictionary * dict );
    25082529int fd_msg_source_get( struct msg * msg, DiamId_t *diamid, size_t * diamidlen );
     2530
     2531/*
     2532 * FUNCTION:    fd_msg_ts_*
     2533 *
     2534 * PARAMETERS:
     2535 *  msg         : A msg object.
     2536 *  ts          : A struct timespec pointer, indexed on CLOCK_REALTIME
     2537 *
     2538 * DESCRIPTION:
     2539 *   Associate or retrieve timestamps meaningful for the message.
     2540 *  A timestamp with a value of { 0, 0 } means: not set.
     2541 *
     2542 * RETURN VALUE:
     2543 *  0           : Operation complete.
     2544 *  !0          : an error occurred.
     2545 */
     2546/* when msg was received from network */
     2547int fd_msg_ts_set_recv( struct msg * msg, struct timespec * ts );
     2548int fd_msg_ts_get_recv( struct msg * msg, struct timespec * ts );
     2549int fd_msg_ts_set_sent( struct msg * msg, struct timespec * ts );
     2550int fd_msg_ts_get_sent( struct msg * msg, struct timespec * ts );
     2551
    25092552
    25102553/*

  • libfdcore/cnxctx.c

    r1078 r1029  
    644644        }
    645645       
     646        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &conn->cc_tls_para.recvon), /* continue */ );
     647       
    646648        return ret;
    647649}
    … …  
    699701                ssize_t ret = 0;
    700702                size_t  received = 0;
     703                struct timespec recv_on;
    701704
    702705                do {
    … …  
    735738                        received += ret;
    736739                }
     740               
     741                /* Piggy-tail the timestamp of reception */
     742                CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
     743                memcpy(newmsg + length, &recv_on, sizeof(struct timespec));
    737744               
    738745                /* We have received a complete message, pass it to the daemon */
    … …  
    923930int fd_tls_rcvthr_core(struct cnxctx * conn, gnutls_session_t session)
    924931{
     932        struct timespec * rcv_on = &conn->cc_tls_para.recvon;
     933       
    925934#ifndef DISABLE_SCTP
    926935        void * ptr = gnutls_transport_get_ptr(session);
    927936        if (ptr != conn) {
    928937                struct sctps_ctx * ctx = (struct sctps_ctx *) ptr;
     938                rcv_on = &ctx->recvon;
    929939        }
    930940#endif /* DISABLE_SCTP */
    … …  
    974984                        received += ret;
    975985                }
     986               
     987                /* The timestamp of the last TLS chunk received for this rebuilt message lives close to the session pointer, we piggyback it */
     988                memcpy(newmsg + length, rcv_on, sizeof(struct timespec));
    976989               
    977990                /* We have received a complete message, pass it to the daemon */

  • libfdcore/core.c

    r1079 r1034  
    209209        CHECK_FCT( fd_conf_init() );
    210210       
     211        /* Initialize the message logging facility */
     212        fd_msg_log_init(fd_g_config->cnf_dict);
     213
    211214        /* Add definitions of the base protocol */
    212215        CHECK_FCT( fd_dict_base_protocol(fd_g_config->cnf_dict) );
    … …  
    304307
    305308
    306 /* Wait for the shutdown to be complete -- this must always be called after fd_core_shutdown to reclaim some resources. */
     309/* Wait for the shutdown to be complete -- this must always be called after fd_core_shutdown to relaim some resources. */
    307310int fd_core_wait_shutdown_complete(void)
    308311{

  • libfdcore/messages.c

    r1078 r1014  
    415415               
    416416                /* Just discard */
    417                 //fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
     417                fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
    418418                CHECK_FCT( fd_msg_free( m ) );
    419419                *msg = NULL;

  • libfdcore/p_ce.c

    r1078 r1027  
    650650        *recv_cnx = NULL;
    651651        if (*cer) {
    652                 //fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
     652                fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
    653653                fd_msg_free(*cer);
    654654                *cer = NULL;
    … …  
    720720        if (req || ((st = fd_peer_getstate(peer)) != STATE_WAITCEA)) {
    721721                if (*msg) {
    722                         //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.", STATE_STR(st));
     722                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.", STATE_STR(st));
    723723                        CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
    724724                        *msg = NULL;
    … …  
    987987cleanup:
    988988        if (msg) {
    989                 //fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
     989                fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
    990990                fd_msg_free(msg);
    991991        }

  • libfdcore/p_out.c

    r1078 r1027  
    4545        int ret;
    4646        uint32_t bkp_hbh = 0;
     47        struct timespec senton;
    4748        struct msg * cpy_for_logs_only;
    4849       
    … …  
    7273        }
    7374       
     75        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &senton), /* ... */ );
     76        CHECK_FCT_DO( fd_msg_ts_set_sent(cpy_for_logs_only, &senton), /* ... */ );
     77       
    7478        /* Log the message */
    75         // fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
     79        fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
     80       
     81        {
     82                struct timespec rcvon, delay;
     83               
     84                (void) fd_msg_ts_get_recv(cpy_for_logs_only, &rcvon);
     85                if (rcvon.tv_sec != 0 || rcvon.tv_nsec != 0) {
     86                        TS_DIFFERENCE( &delay, &rcvon, &senton);
     87                        fd_msg_log( FD_MSG_LOG_TIMING, cpy_for_logs_only, "Forwarded in %ld.%6.6ld sec", (long)delay.tv_sec, delay.tv_nsec/1000);
     88                } else { /* We log the answer time only for answers generated locally */
     89                        if (!msg_is_a_req) {
     90                                /* get the matching request */
     91                                struct msg * req;
     92                                struct timespec reqrcvon;
     93                                (void) fd_msg_answ_getq(cpy_for_logs_only, &req);
     94                                (void) fd_msg_ts_get_recv(req, &reqrcvon);
     95                                TS_DIFFERENCE( &delay, &reqrcvon, &senton);
     96                                fd_msg_log( FD_MSG_LOG_TIMING, cpy_for_logs_only, "Answered in %ld.%6.6ld sec", (long)delay.tv_sec, delay.tv_nsec/1000);
     97                        }
     98                }
     99        }
    76100       
    77101        /* Send the message */
    … …  
    98122        CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &msg),
    99123                {
    100                         //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
     124                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
    101125                        CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */);
    102126                } );
    … …  
    131155                        {
    132156                                if (msg) {
    133                                         //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
     157                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
    134158                                        fd_msg_free(msg);
    135159                                }
    … …  
    183207                        {
    184208                                if (msg) {
    185                                         //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)", strerror(ret) );
     209                                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)", strerror(ret) );
    186210                                        fd_msg_free(*msg);
    187211                                        *msg = NULL;

  • libfdcore/p_psm.c

    r1078 r1033  
    241241                        case FDEVP_CNX_INCOMING: {
    242242                                struct cnx_incoming * evd = ev->data;
    243                                 //fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
     243                                fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
    244244                                CHECK_FCT_DO( fd_msg_free(evd->cer), /* continue */);
    245245                                fd_cnx_destroy(evd->cnx);
    … …  
    489489                struct msg * msg = NULL;
    490490                struct msg_hdr * hdr;
     491                struct timespec rcvon;
     492               
     493                /* Retrieve the piggytailed timestamp */
     494                memcpy(&rcvon, ev_data+ev_sz, sizeof(struct timespec));
    491495               
    492496                /* Parse the received buffer */
    … …  
    499503                        } );
    500504                       
     505                CHECK_FCT_DO( fd_msg_ts_set_recv(msg, &rcvon), /* ... */ );
     506               
    501507                /* If the current state does not allow receiving messages, just drop it */
    502508                if (cur_state == STATE_CLOSED) {
    503509                        /* In such case, just discard the message */
    504                         //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Purged from peer '%s''s queue (CLOSED state).", peer->p_hdr.info.pi_diamid );
     510                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Purged from peer '%s''s queue (CLOSED state).", peer->p_hdr.info.pi_diamid );
    505511                        fd_msg_free(msg);
    506512                        goto psm_loop;
    … …  
    508514               
    509515                /* Log incoming message */
    510                 //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) );
     516                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) );
    511517       
    512518                /* Extract the header */
    … …  
    519525                        CHECK_FCT_DO( fd_p_sr_fetch(&peer->p_sr, hdr->msg_hbhid, &req), goto psm_end );
    520526                        if (req == NULL) {
    521                                 //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
     527                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
    522528                                fd_msg_free(msg);
    523529                                goto psm_loop;
    … …  
    529535                        /* Display the delay to receive the answer */
    530536                        {
    531                                 //fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %ld.%6.6ld sec.", (long)delay.tv_sec, delay.tv_nsec / 1000 );
     537                                struct timespec reqsent, delay;
     538                                (void) fd_msg_ts_get_sent(req, &reqsent);
     539                                TS_DIFFERENCE( &delay, &reqsent, &rcvon );
     540                                fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %ld.%6.6ld sec.", (long)delay.tv_sec, delay.tv_nsec / 1000 );
    532541                        }
    533542                } else {
    … …  
    577586                                default:
    578587                                        /* In such case, just discard the message */
    579                                         //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) );
     588                                        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) );
    580589                                        fd_msg_free(msg);
    581590                        }
    … …  
    594603                                        if (msg) {
    595604                                                /* Only if an error occurred & the message was not saved / dumped */
    596                                                 //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
     605                                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
    597606                                                CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
    598607                                        }
    … …  
    643652                                /* Cleanup the message if not done */
    644653                                if (msg) {
    645                                         //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
     654                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
    646655                                        CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
    647656                                        msg = NULL;
    … …  
    651660                /* At this point the message must have been fully handled already */
    652661                if (msg) {
    653                         //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error ('%s'): unhandled message.", peer->p_hdr.info.pi_diamid );
     662                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error ('%s'): unhandled message.", peer->p_hdr.info.pi_diamid );
    654663                        fd_msg_free(msg);
    655664                }
    … …  
    737746                }
    738747                if (params->cer) {
    739                         //fd_msg_log( FD_MSG_LOG_DROPPED, params->cer, "Internal error: this CER was not handled as expected." );
     748                        fd_msg_log( FD_MSG_LOG_DROPPED, params->cer, "Internal error: this CER was not handled as expected." );
    740749                        CHECK_FCT_DO( fd_msg_free(params->cer), );
    741750                        params->cer = NULL;

  • libfdcore/p_sr.c

    r1078 r1052  
    119119        /* If the callback did not dispose of the message, do it now */
    120120        if (ed->request) {
    121                 //fd_msg_log(FD_MSG_LOG_DROPPED, ed->request, "Expiration period completed without an answer, and the expiry callback did not dispose of the message.");
     121                fd_msg_log(FD_MSG_LOG_DROPPED, ed->request, "Expiration period completed without an answer, and the expiry callback did not dispose of the message.");
    122122                CHECK_FCT_DO( fd_msg_free(ed->request), /* ignore */ );
    123123        }
    … …  
    325325                        CHECK_FCT_DO( ret = fd_fifo_post(fd_g_outgoing, &sr->req),
    326326                                {
    327                                         //fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
     327                                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
    328328                                        CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */)
    329329                                });
    330330                } else {
    331331                        /* Just free the request. */
    332                         //fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Sent & unanswered local message discarded during failover." );
     332                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Sent & unanswered local message discarded during failover." );
    333333                        CHECK_FCT_DO(fd_msg_free(sr->req), /* Ignore */);
    334334                }

  • libfdcore/peers.c

    r1078 r1027  
    245245                        {
    246246                                /* fallback: destroy the message */
    247                                 //fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
     247                                fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
    248248                                CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */)
    249249                        } );

  • libfdcore/queues.c

    r1078 r767  
    7474               
    7575                /* We got one! */
    76                 //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
     76                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
    7777                fd_msg_free(msg);
    7878        }

  • libfdcore/routing_dispatch.c

    r1078 r1055  
    393393
    394394                        if (!peer) {
    395                                 //fd_msg_log(FD_MSG_LOG_DROPPED, *pmsg, "Unable to send error '%s' to deleted peer '%s' in reply to this message.", error_code, id);
     395                                fd_msg_log(FD_MSG_LOG_DROPPED, *pmsg, "Unable to send error '%s' to deleted peer '%s' in reply to this message.", error_code, id);
    396396                                fd_msg_free(*pmsg);
    397397                                *pmsg = NULL;
    … …  
    450450                        }
    451451                        if (msgptr) {   /* another error happen'd */
    452                                 //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
     452                                fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
    453453                                CHECK_FCT_DO( fd_msg_free(msgptr), /* continue */);
    454454                        }
    … …  
    511511                               
    512512                                if (!is_req) {
    513                                         //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
     513                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
    514514                                        fd_msg_free(msgptr);
    515515                                        break;
    … …  
    756756                        CHECK_FCT_DO( ret = (*rh->rt_fwd_cb)(rh->cbdata, &msgptr),
    757757                                {
    758                                         //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
     758                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
    759759                                        fd_msg_free(msgptr);
    760760                                        msgptr = NULL;
    … …  
    815815                CHECK_FCT( fd_peer_getbyid( qry_src, qry_src_len, 0, (void *) &peer ) );
    816816                if (fd_peer_getstate(peer) != STATE_OPEN) {
    817                         //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
     817                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
    818818                        fd_msg_free(msgptr);
    819819                        return 0;
    … …  
    900900                        CHECK_FCT_DO( ret = (*rh->rt_out_cb)(rh->cbdata, msgptr, candidates),
    901901                                {
    902                                         //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
     902                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
    903903                                        fd_msg_free(msgptr);
    904904                                        msgptr = NULL;
    … …  
    948948        /* If the message has not been sent, return an error */
    949949        if (msgptr) {
    950                 //fd_msg_log( FD_MSG_LOG_NODELIVER, msgptr, "No suitable candidate to route the message to." );
     950                fd_msg_log( FD_MSG_LOG_NODELIVER, msgptr, "No suitable candidate to route the message to." );
    951951                return_error( &msgptr, "DIAMETER_UNABLE_TO_DELIVER", "No suitable candidate to route the message to", NULL);
    952952        }

  • libfdcore/sctp.c

    r1078 r1027  
    10681068        size_t                   mempagesz = sysconf(_SC_PAGESIZE); /* We alloc buffer by memory pages for efficiency */
    10691069        int                      timedout = 0;
     1070        struct timespec          recv_on;
    10701071       
    10711072        TRACE_ENTRY("%p %p %p %p %p", conn, strid, buf, len, event);
    … …  
    11881189        }
    11891190       
     1191        /* Piggy-tail the timestamp of reception */
     1192        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
     1193        memcpy(data + datasize, &recv_on, sizeof(struct timespec));
     1194               
    11901195        /* From this point, we have received a message */
    11911196        *event = FDEVP_CNX_MSG_RECV;

  • libfdcore/server.c

    r1078 r1061  
    169169       
    170170        /* Log incoming message */
    171         //fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn) );
     171        fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn) );
    172172       
    173173        /* We expect a CER, it must parse with our dictionary and rules */
    … …  
    195195        /* Cleanup the parsed message if any */
    196196        if (msg) {
    197                 //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received invalid/unexpected message from connecting client '%s'", fd_cnx_getid(c->conn) );
     197                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received invalid/unexpected message from connecting client '%s'", fd_cnx_getid(c->conn) );
    198198                CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
    199199        }

  • libfdproto/CMakeLists.txt

    r1080 r922  
    1313        log.c
    1414        messages.c
     15        msg_log.c
    1516        ostr.c
    1617        portability.c
    1718        rt_data.c
    1819        sessions.c
    19         utils.c
    2020        )
    2121

  • libfdproto/dispatch.c

    r1078 r1017  
    9797                CHECK_FCT_DO( (r = (*hdl->cb)(msg, avp, sess, hdl->opaque, action)),
    9898                        {
    99                                 //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: a DISPATCH callback returned an error (%s)", strerror(r));
     99                                fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: a DISPATCH callback returned an error (%s)", strerror(r));
    100100                                fd_msg_free(*msg);
    101101                                *msg = NULL;

  • libfdproto/messages.c

    r1078 r1062  
    129129        DiamId_t                 msg_src_id;            /* Diameter Id of the peer this message was received from. This string is malloc'd and must be freed */
    130130        size_t                   msg_src_id_len;        /* cached length of this string */
     131        struct timespec          msg_ts_rcv;            /* Timestamp when this message was received from the network */
     132        struct timespec          msg_ts_sent;           /* Timestamp when this message was sent to the network */
    131133       
    132134};
    … …  
    732734        }
    733735       
     736        if ((msg->msg_ts_rcv.tv_sec != 0) || (msg->msg_ts_rcv.tv_nsec != 0)) {
     737                tsoffset += strftime(buftime + tsoffset, sizeof(buftime) - tsoffset, "%D,%T", localtime_r( &msg->msg_ts_rcv.tv_sec , &tm ));
     738                tsoffset += snprintf(buftime + tsoffset, sizeof(buftime) - tsoffset, ".%6.6ld", msg->msg_ts_rcv.tv_nsec / 1000);
     739                CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "Received: %s|", INOBJHDRVAL, buftime) );
     740        }
     741        if ((msg->msg_ts_sent.tv_sec != 0) || (msg->msg_ts_sent.tv_nsec != 0)) {
     742                tsoffset += strftime(buftime + tsoffset, sizeof(buftime) - tsoffset, "%D,%T", localtime_r( &msg->msg_ts_sent.tv_sec , &tm ));
     743                tsoffset += snprintf(buftime + tsoffset, sizeof(buftime) - tsoffset, ".%6.6ld", msg->msg_ts_sent.tv_nsec / 1000);
     744                CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "Sent    : %s|", INOBJHDRVAL, buftime) );
     745        }
     746       
    734747        if (!msg->msg_model) {
    735748               
    … …  
    985998
    986999/* Dump full message */
    987 // TODO: need align with new prototype & behavior
    988 void fd_msg_dump_full_TODO ( int level, struct dictionary *dict, const char *prefix, msg_or_avp *obj )
     1000void fd_msg_dump_full ( int level, struct dictionary *dict, const char *prefix, msg_or_avp *obj )
    9891001{
    9901002        msg_or_avp * ref = obj;
    … …  
    13491361       
    13501362        /* done */
     1363        return 0;
     1364}
     1365
     1366int fd_msg_ts_set_recv( struct msg * msg, struct timespec * ts )
     1367{
     1368        TRACE_ENTRY("%p %p", msg, ts);
     1369       
     1370        /* Check we received valid parameters */
     1371        CHECK_PARAMS( CHECK_MSG(msg) );
     1372        CHECK_PARAMS( ts );
     1373       
     1374        memcpy(&msg->msg_ts_rcv, ts, sizeof(struct timespec));
     1375        return 0;
     1376}
     1377
     1378int fd_msg_ts_get_recv( struct msg * msg, struct timespec * ts )
     1379{
     1380        TRACE_ENTRY("%p %p", msg, ts);
     1381       
     1382        /* Check we received valid parameters */
     1383        CHECK_PARAMS( CHECK_MSG(msg) );
     1384        CHECK_PARAMS( ts );
     1385       
     1386        memcpy(ts, &msg->msg_ts_rcv, sizeof(struct timespec));
     1387        return 0;
     1388}
     1389
     1390int fd_msg_ts_set_sent( struct msg * msg, struct timespec * ts )
     1391{
     1392        TRACE_ENTRY("%p %p", msg, ts);
     1393       
     1394        /* Check we received valid parameters */
     1395        CHECK_PARAMS( CHECK_MSG(msg) );
     1396        CHECK_PARAMS( ts );
     1397       
     1398        memcpy(&msg->msg_ts_sent, ts, sizeof(struct timespec));
     1399        return 0;
     1400}
     1401
     1402int fd_msg_ts_get_sent( struct msg * msg, struct timespec * ts )
     1403{
     1404        TRACE_ENTRY("%p %p", msg, ts);
     1405       
     1406        /* Check we received valid parameters */
     1407        CHECK_PARAMS( CHECK_MSG(msg) );
     1408        CHECK_PARAMS( ts );
     1409       
     1410        memcpy(ts, &msg->msg_ts_sent, sizeof(struct timespec));
    13511411        return 0;
    13521412}
    … …  
    25792639                        *action = DISP_ACT_ERROR;
    25802640                } else {
    2581                         //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Received this answer to a local query with an unsupported application %d", (*msg)->msg_public.msg_appl);
     2641                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Received this answer to a local query with an unsupported application %d", (*msg)->msg_public.msg_appl);
    25822642                        fd_msg_free(*msg);
    25832643                        *msg = NULL;

  • tests/tests.h

    r1078 r1034  
    216216        CHECK( 0, fd_conf_init() );
    217217
     218        /* Initialize the message logging facility */
     219        fd_msg_log_init(fd_g_config->cnf_dict);
     220
    218221        /* Add definitions of the base protocol */
    219222        CHECK( 0, fd_dict_base_protocol(fd_g_config->cnf_dict) );
Note: See TracChangeset for help on using the changeset viewer.