Changeset 1078:74bba7975864 in freeDiameter for libfdcore

Timestamp:

Apr 30, 2013, 4:37:57 PM (11 years ago)

Author:

Sebastien Decugis <sdecugis@freediameter.net>

Branch:

default

Phase:

public

Message:

Cleanup the timing data and fd_msg_log feature that will be replaced by the new hooks mechanism. Kept the calls to fd_msg_log in comments to find the locations easily. WORK IN PROGRESS.

Location:

libfdcore

Files:

• cnxctx.c (modified) (5 diffs)
• core.c (modified) (1 diff)
• messages.c (modified) (1 diff)
• p_ce.c (modified) (3 diffs)
• p_out.c (modified) (5 diffs)
• p_psm.c (modified) (11 diffs)
• p_sr.c (modified) (2 diffs)
• peers.c (modified) (1 diff)
• queues.c (modified) (1 diff)
• routing_dispatch.c (modified) (7 diffs)
• sctp.c (modified) (2 diffs)
• server.c (modified) (2 diffs)

libfdcore/cnxctx.c

@@ -644 +644 @@
         }
         
-        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &conn->cc_tls_para.recvon), /* continue */ );
-        
         return ret;
 }
@@ -701 +699 @@
                 ssize_t ret = 0;
                 size_t  received = 0;
-                struct timespec recv_on;
 
                 do {
@@ -738 +735 @@
                         received += ret;
                 }
-                
-                /* Piggy-tail the timestamp of reception */
-                CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
-                memcpy(newmsg + length, &recv_on, sizeof(struct timespec));
                 
                 /* We have received a complete message, pass it to the daemon */
@@ -930 +923 @@
 int fd_tls_rcvthr_core(struct cnxctx * conn, gnutls_session_t session)
 {
-        struct timespec * rcv_on = &conn->cc_tls_para.recvon;
-        
 #ifndef DISABLE_SCTP
         void * ptr = gnutls_transport_get_ptr(session);
         if (ptr != conn) {
                 struct sctps_ctx * ctx = (struct sctps_ctx *) ptr;
-                rcv_on = &ctx->recvon;
         }
 #endif /* DISABLE_SCTP */
@@ -984 +974 @@
                         received += ret;
                 }
-                
-                /* The timestamp of the last TLS chunk received for this rebuilt message lives close to the session pointer, we piggyback it */
-                memcpy(newmsg + length, rcv_on, sizeof(struct timespec));
                 
                 /* We have received a complete message, pass it to the daemon */

libfdcore/core.c

@@ -209 +209 @@
         CHECK_FCT( fd_conf_init() );
         
-        /* Initialize the message logging facility */
-        fd_msg_log_init(fd_g_config->cnf_dict);
-
         /* Add definitions of the base protocol */
         CHECK_FCT( fd_dict_base_protocol(fd_g_config->cnf_dict) );

libfdcore/messages.c

@@ -415 +415 @@
                 
                 /* Just discard */
-                fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
+                //fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
                 CHECK_FCT( fd_msg_free( m ) );
                 *msg = NULL;

libfdcore/p_ce.c

@@ -650 +650 @@
         *recv_cnx = NULL;
         if (*cer) {
-                fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
+                //fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
                 fd_msg_free(*cer);
                 *cer = NULL;
@@ -720 +720 @@
         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));
+                        //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.", STATE_STR(st));
                         CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
                         *msg = NULL;
@@ -987 +987 @@
 cleanup:
         if (msg) {
-                fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
+                //fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
                 fd_msg_free(msg);
         }

libfdcore/p_out.c

@@ -45 +45 @@
         int ret;
         uint32_t bkp_hbh = 0;
-        struct timespec senton;
         struct msg * cpy_for_logs_only;
         
@@ -73 +72 @@
         }
         
-        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &senton), /* ... */ );
-        CHECK_FCT_DO( fd_msg_ts_set_sent(cpy_for_logs_only, &senton), /* ... */ );
-        
         /* Log the message */
-        fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
-        
-        {
-                struct timespec rcvon, delay;
-                
-                (void) fd_msg_ts_get_recv(cpy_for_logs_only, &rcvon);
-                if (rcvon.tv_sec != 0 || rcvon.tv_nsec != 0) {
-                        TS_DIFFERENCE( &delay, &rcvon, &senton);
-                        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);
-                } else { /* We log the answer time only for answers generated locally */
-                        if (!msg_is_a_req) {
-                                /* get the matching request */
-                                struct msg * req;
-                                struct timespec reqrcvon;
-                                (void) fd_msg_answ_getq(cpy_for_logs_only, &req);
-                                (void) fd_msg_ts_get_recv(req, &reqrcvon);
-                                TS_DIFFERENCE( &delay, &reqrcvon, &senton);
-                                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);
-                        }
-                }
-        }
+        // fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
         
         /* Send the message */
@@ -122 +98 @@
         CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &msg),
                 {
-                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
+                        //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
                         CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */);
                 } );
@@ -155 +131 @@
                         {
                                 if (msg) {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
                                         fd_msg_free(msg);
                                 }
@@ -207 +183 @@
                         {
                                 if (msg) {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)", strerror(ret) );
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)", strerror(ret) );
                                         fd_msg_free(*msg);
                                         *msg = NULL;

libfdcore/p_psm.c

@@ -241 +241 @@
                         case FDEVP_CNX_INCOMING: {
                                 struct cnx_incoming * evd = ev->data;
-                                fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
+                                //fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
                                 CHECK_FCT_DO( fd_msg_free(evd->cer), /* continue */);
                                 fd_cnx_destroy(evd->cnx);
@@ -489 +489 @@
                 struct msg * msg = NULL;
                 struct msg_hdr * hdr;
-                struct timespec rcvon;
-                
-                /* Retrieve the piggytailed timestamp */
-                memcpy(&rcvon, ev_data+ev_sz, sizeof(struct timespec));
                 
                 /* Parse the received buffer */
@@ -503 +499 @@
                         } );
                         
-                CHECK_FCT_DO( fd_msg_ts_set_recv(msg, &rcvon), /* ... */ );
-                
                 /* 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_msg_log( FD_MSG_LOG_DROPPED, msg, "Purged from peer '%s''s queue (CLOSED state).", peer->p_hdr.info.pi_diamid );
                         fd_msg_free(msg);
                         goto psm_loop;
@@ -514 +508 @@
                 
                 /* 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) );
+                //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 */
@@ -525 +519 @@
                         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_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
                                 fd_msg_free(msg);
                                 goto psm_loop;
@@ -535 +529 @@
                         /* Display the delay to receive the answer */
                         {
-                                struct timespec reqsent, delay;
-                                (void) fd_msg_ts_get_sent(req, &reqsent);
-                                TS_DIFFERENCE( &delay, &reqsent, &rcvon );
-                                fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %ld.%6.6ld sec.", (long)delay.tv_sec, delay.tv_nsec / 1000 );
+                                //fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %ld.%6.6ld sec.", (long)delay.tv_sec, delay.tv_nsec / 1000 );
                         }
                 } else {
@@ -586 +577 @@
                                 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) );
+                                        //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) );
                                         fd_msg_free(msg);
                         }
@@ -603 +594 @@
                                         if (msg) {
                                                 /* Only if an error occurred & the message was not saved / dumped */
-                                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)", strerror(ret) );
+                                                //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);
                                         }
@@ -652 +643 @@
                                 /* Cleanup the message if not done */
                                 if (msg) {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
                                         CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
                                         msg = NULL;
@@ -660 +651 @@
                 /* At this point the message must have been fully handled already */
                 if (msg) {
-                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error ('%s'): unhandled message.", peer->p_hdr.info.pi_diamid );
+                        //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error ('%s'): unhandled message.", peer->p_hdr.info.pi_diamid );
                         fd_msg_free(msg);
                 }
@@ -746 +737 @@
                 }
                 if (params->cer) {
-                        fd_msg_log( FD_MSG_LOG_DROPPED, params->cer, "Internal error: this CER was not handled as expected." );
+                        //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;

libfdcore/p_sr.c

@@ -119 +119 @@
         /* If the callback did not dispose of the message, do it now */
         if (ed->request) {
-                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.");
+                //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.");
                 CHECK_FCT_DO( fd_msg_free(ed->request), /* ignore */ );
         }
@@ -325 +325 @@
                         CHECK_FCT_DO( ret = fd_fifo_post(fd_g_outgoing, &sr->req),
                                 {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
                                         CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */)
                                 });
                 } else {
                         /* Just free the request. */
-                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Sent & unanswered local message discarded during failover." );
+                        //fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Sent & unanswered local message discarded during failover." );
                         CHECK_FCT_DO(fd_msg_free(sr->req), /* Ignore */);
                 }

libfdcore/peers.c

@@ -245 +245 @@
                         {
                                 /* fallback: destroy the message */
-                                fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
+                                //fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
                                 CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */)
                         } );

libfdcore/queues.c

@@ -74 +74 @@
                 
                 /* We got one! */
-                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
+                //fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
                 fd_msg_free(msg);
         }

libfdcore/routing_dispatch.c

@@ -393 +393 @@
 
                         if (!peer) {
-                                fd_msg_log(FD_MSG_LOG_DROPPED, *pmsg, "Unable to send error '%s' to deleted peer '%s' in reply to this message.", error_code, id);
+                                //fd_msg_log(FD_MSG_LOG_DROPPED, *pmsg, "Unable to send error '%s' to deleted peer '%s' in reply to this message.", error_code, id);
                                 fd_msg_free(*pmsg);
                                 *pmsg = NULL;
@@ -450 +450 @@
                         }
                         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));
+                                //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 */);
                         }
@@ -511 +511 @@
                                 
                                 if (!is_req) {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
                                         fd_msg_free(msgptr);
                                         break;
@@ -756 +756 @@
                         CHECK_FCT_DO( ret = (*rh->rt_fwd_cb)(rh->cbdata, &msgptr),
                                 {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
                                         fd_msg_free(msgptr);
                                         msgptr = NULL;
@@ -815 +815 @@
                 CHECK_FCT( fd_peer_getbyid( qry_src, qry_src_len, 0, (void *) &peer ) );
                 if (fd_peer_getstate(peer) != STATE_OPEN) {
-                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
+                        //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
                         fd_msg_free(msgptr);
                         return 0;
@@ -900 +900 @@
                         CHECK_FCT_DO( ret = (*rh->rt_out_cb)(rh->cbdata, msgptr, candidates),
                                 {
-                                        fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
+                                        //fd_msg_log( FD_MSG_LOG_DROPPED, msgptr, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
                                         fd_msg_free(msgptr);
                                         msgptr = NULL;
@@ -948 +948 @@
         /* If the message has not been sent, return an error */
         if (msgptr) {
-                fd_msg_log( FD_MSG_LOG_NODELIVER, msgptr, "No suitable candidate to route the message to." );
+                //fd_msg_log( FD_MSG_LOG_NODELIVER, msgptr, "No suitable candidate to route the message to." );
                 return_error( &msgptr, "DIAMETER_UNABLE_TO_DELIVER", "No suitable candidate to route the message to", NULL);
         }

libfdcore/sctp.c

@@ -1068 +1068 @@
         size_t                   mempagesz = sysconf(_SC_PAGESIZE); /* We alloc buffer by memory pages for efficiency */
         int                      timedout = 0;
-        struct timespec          recv_on;
         
         TRACE_ENTRY("%p %p %p %p %p", conn, strid, buf, len, event);
@@ -1189 +1188 @@
         }
         
-        /* Piggy-tail the timestamp of reception */
-        CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
-        memcpy(data + datasize, &recv_on, sizeof(struct timespec));
-                
         /* From this point, we have received a message */
         *event = FDEVP_CNX_MSG_RECV;

libfdcore/server.c

@@ -169 +169 @@
         
         /* Log incoming message */
-        fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn) );
+        //fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from new client '%s'", bufsz, fd_cnx_getid(c->conn) );
         
         /* We expect a CER, it must parse with our dictionary and rules */
@@ -195 +195 @@
         /* 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) );
+                //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 */);
         }