Changeset 688:8c3dc8584dab in freeDiameter

Timestamp:

Jan 19, 2011, 7:05:30 PM (13 years ago)

Author:

Sebastien Decugis <sdecugis@nict.go.jp>

Branch:

default

Phase:

public

Message:

Prepared capability for messages logging to separate files / folders

Files:

• doc/dbg_interactive.py.sample (modified) (1 diff)
• extensions/app_radgw/rgwx_acct.c (modified) (1 diff)
• extensions/dbg_interactive/messages.i (modified) (1 diff)
• include/freeDiameter/libfdproto.h (modified) (2 diffs)
• libfdcore/core.c (modified) (1 diff)
• libfdcore/messages.c (modified) (2 diffs)
• libfdcore/p_ce.c (modified) (3 diffs)
• libfdcore/p_out.c (modified) (6 diffs)
• libfdcore/p_psm.c (modified) (9 diffs)
• libfdcore/p_sr.c (modified) (3 diffs)
• libfdcore/peers.c (modified) (1 diff)
• libfdcore/queues.c (modified) (1 diff)
• libfdcore/routing_dispatch.c (modified) (8 diffs)
• libfdcore/server.c (modified) (3 diffs)
• libfdproto/messages.c (modified) (6 diffs)
• tests/testcnx.c (modified) (1 diff)

doc/dbg_interactive.py.sample

@@ -364 +364 @@
 a_msg = msg()
 a_msg.dump()
+a_msg.log(FD_MSG_LOG_DROPPED, "Check libfdproto for more details. Configure with fd_msg_log_config.")
 del a_msg
 

extensions/app_radgw/rgwx_acct.c

@@ -1215 +1215 @@
 out:
         if (answer && *answer) {
-                TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding...");
+                TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding anyway...");
                 fd_msg_dump_walk( INFO, *answer );
                 fd_msg_free(*answer);

extensions/dbg_interactive/messages.i

@@ -254 +254 @@
         }
         
+        /* Log to file (depending on config)  */
+        void log ( enum fd_msg_log_cause cause, char * message ) {
+                fd_msg_log( cause, $self, message );
+        }
+        
         /* Model */
         struct dict_object * model() {

include/freeDiameter/libfdproto.h

@@ -2055 +2055 @@
         FD_MSG_LOG_DROPPED = 0,  /* message has been dropped by the framework */ 
         FD_MSG_LOG_RECEIVED,     /* message received from the network */ 
-        FD_MSG_LOG_SENT          /* message sent to another peer */ 
-};
-#define FD_MSG_LOG_MAX FD_MSG_LOG_SENT
+        FD_MSG_LOG_SENT,         /* message sent to another peer */ 
+        FD_MSG_LOG_NODELIVER     /* message could not be delivered to any peer */ 
+};
+#define FD_MSG_LOG_MAX FD_MSG_LOG_NODELIVER
 void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... );
 
@@ -2067 +2068 @@
 };
 int fd_msg_log_config(enum fd_msg_log_cause cause, enum fd_msg_log_method method, const char * arg);
+void ml_conf_init(struct dictionary *dict);
 
 /*********************************************/

libfdcore/core.c

@@ -195 +195 @@
         fd_g_config = &g_conf;
         CHECK_FCT( fd_conf_init() );
+        
+        /* Initialize the message logging facility */
+        ml_conf_init(fd_g_config->cnf_dict);
 
         /* Add definitions of the base protocol */

libfdcore/messages.c

@@ -313 +313 @@
                 return ret;
         
-        fd_log_debug("The following message does not comply to the dictionary and/or rules (%s):\n", pei.pei_errcode);
-        fd_msg_dump_walk(NONE, m);
+        TRACE_DEBUG(INFO, "A message does not comply to the dictionary and/or rules (%s)", pei.pei_errcode);
+        fd_msg_dump_walk(FULL, m);
         
         CHECK_FCT( fd_msg_hdr(m, &hdr) );
@@ -364 +364 @@
                 
                 /* Just discard */
+                fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
                 CHECK_FCT( fd_msg_free( m ) );
                 *msg = NULL;

libfdcore/p_ce.c

@@ -598 +598 @@
         fd_cnx_destroy(recv_cnx);
         if (*cer) {
+                fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
                 fd_msg_free(*cer);
                 *cer = NULL;
@@ -665 +666 @@
         if (req || (peer->p_hdr.info.runtime.pir_state != STATE_WAITCEA)) {
                 if (*msg) {
-                        fd_log_debug("Received CER/CEA message while in state '%s', discarded.\n", STATE_STR(peer->p_hdr.info.runtime.pir_state));
-                        fd_msg_dump_walk(NONE, *msg);
+                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Received CER/CEA while in '%s' state.\n", STATE_STR(peer->p_hdr.info.runtime.pir_state));
                         CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
                         *msg = NULL;
@@ -911 +911 @@
 cleanup:
         if (msg) {
+                fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
                 fd_msg_free(msg);
         }

libfdcore/p_out.c

@@ -60 +60 @@
         }
         
-        /* Log the message */
-        if (TRACE_BOOL(FULL)) {
-                CHECK_FCT_DO(  fd_msg_update_length(*msg), /* continue */  );
-                TRACE_DEBUG(FULL, "Sending the following message on connection '%s':", fd_cnx_getid(cnx));
-                fd_msg_dump_walk(FULL, *msg);
-        }
-        
         /* Create the message buffer */
         CHECK_FCT(fd_msg_bufferize( *msg, &buf, &sz ));
         pthread_cleanup_push( free, buf );
+        
+        /* Log the message */
+        fd_msg_log( FD_MSG_LOG_SENT, *msg, "Sent to '%s'", fd_cnx_getid(cnx));
         
         /* Save a request before sending so that there is no race condition with the answer */
@@ -93 +89 @@
         struct msg *msg = arg;
         CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &msg),
-                        CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */));
+                {
+                        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? */);
+                } );
 }
 
@@ -112 +111 @@
         while (1) {
                 struct msg * msg;
+                int ret;
                 
                 /* Retrieve next message to send */
@@ -120 +120 @@
                 
                 /* Send the message, log any error */
-                CHECK_FCT_DO( 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->p_sr),
                         {
                                 if (msg) {
-                                        fd_log_debug("An error occurred while sending this message, it was lost:\n");
-                                        fd_msg_dump_walk(NONE, msg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
                                         fd_msg_free(msg);
                                 }
@@ -151 +150 @@
                 
         } else {
+                int ret;
                 uint32_t *hbh = NULL;
                 
@@ -161 +161 @@
 
                 /* Do send the message */
-                CHECK_FCT_DO( do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
+                CHECK_FCT_DO( ret = do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
                         {
                                 if (msg) {
-                                        fd_log_debug("An error occurred while sending this message, it was lost:\n");
-                                        fd_msg_dump_walk(NONE, *msg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
                                         fd_msg_free(*msg);
                                         *msg = NULL;

libfdcore/p_psm.c

@@ -166 +166 @@
                         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." );
                                 CHECK_FCT_DO( fd_msg_free(evd->cer), /* continue */);
                                 fd_cnx_destroy(evd->cnx);
@@ -394 +395 @@
                         } );
                 
-                TRACE_DEBUG(FULL, "Received a message (%zdb) from '%s'", ev_sz, peer->p_hdr.info.pi_diamid);
-                if (TRACE_BOOL(FULL+1)) {
-                        CHECK_FCT_DO( fd_msg_parse_dict( msg, fd_g_config->cnf_dict, NULL ), );
-                        fd_msg_dump_walk(FULL, msg);
-                } else {
-                        fd_msg_dump_one(FULL, msg);
-                }
+                /* Log incoming message */
+                fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from '%s'", ev_sz, peer->p_hdr.info.pi_diamid );
         
                 /* Extract the header */
@@ -411 +407 @@
                         CHECK_FCT_DO( fd_p_sr_fetch(&peer->p_sr, hdr->msg_hbhid, &req), goto psm_end );
                         if (req == NULL) {
-                                fd_log_debug("Received a Diameter answer message with no corresponding sent request, discarding.\n");
-                                fd_msg_dump_walk(NONE, msg);
+                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
                                 fd_msg_free(msg);
                                 goto psm_loop;
@@ -453 +448 @@
                                 default:
                                         /* In such case, just discard the message */
-                                        fd_log_debug("Received a routable message while not in OPEN state from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
-                                        fd_msg_dump_walk(NONE, msg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received from peer '%s' while connection was not in OPEN state.", peer->p_hdr.info.pi_diamid );
                                         fd_msg_free(msg);
                         }
@@ -468 +462 @@
                                 if (msg) {
                                         /* Send the error back to the peer */
-                                        CHECK_FCT_DO( fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED), /* In case of error the message has already been dumped */ );
+                                        CHECK_FCT_DO( ret = fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED),  );
                                         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)\n", strerror(ret) );
                                                 CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
                                         }
@@ -498 +494 @@
                         default:
                                 /* Unknown / unexpected / invalid message */
-                                fd_log_debug("Received an unknown local message from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
-                                fd_msg_dump_walk(NONE, msg);
+                                TRACE_DEBUG(INFO, "Invalid non-routable command received: %u.", hdr->msg_code);
                                 if (hdr->msg_flags & CMD_FLAG_REQUEST) {
                                         do {
@@ -518 +513 @@
                                 /* 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 );
                                         CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
                                         msg = NULL;
@@ -525 +521 @@
                 /* At this point the message must have been fully handled already */
                 if (msg) {
-                        fd_log_debug("Internal error: unhandled message (discarded)!\n");
-                        fd_msg_dump_walk(NONE, msg);
+                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: unhandled message.", peer->p_hdr.info.pi_diamid );
                         fd_msg_free(msg);
                 }
@@ -602 +597 @@
                 }
                 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;

libfdcore/p_sr.c

@@ -109 +109 @@
         /* If the callback did not dispose of the message, do it now */
         if (expired_req) {
+                fd_msg_log(FD_MSG_LOG_DROPPED, expired_req, "Expiration period completed without an answer, and the expiry callback did not dispose of the message.");
                 CHECK_FCT_DO( fd_msg_free(expired_req), /* ignore */ );
         }
@@ -296 +297 @@
                 if (fd_msg_is_routable(sr->req)) {
                         struct msg_hdr * hdr = NULL;
+                        int ret;
                         
                         /* Set the 'T' flag */
@@ -303 +305 @@
                         
                         /* Requeue for sending to another peer */
-                        CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &sr->req),
-                                        CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */));
+                        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) );
+                                        CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */)
+                                });
                 } else {
-                        /* Just free the request... */
+                        /* Just free the request. */
+                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Local message discarded during failover" );
                         CHECK_FCT_DO(fd_msg_free(sr->req), /* Ignore */);
                 }

libfdcore/peers.c

@@ -211 +211 @@
         while ( fd_fifo_tryget(peer->p_tosend, &m) == 0 ) {
                 CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &m), 
+                        {
                                 /* fallback: destroy the message */
-                                CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */));
+                                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_log_debug("The following message is lost because the daemon is stopping:\n");
-                fd_msg_dump_walk(NONE, msg);
+                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
                 fd_msg_free(msg);
         }

libfdcore/routing_dispatch.c

@@ -409 +409 @@
 
                         if (!peer) {
-                                TRACE_DEBUG(INFO, "Unable to send error '%s' to deleted peer '%s' in reply to:", error_code, id);
-                                fd_msg_dump_walk(INFO, *pmsg);
+                                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;
@@ -467 +466 @@
                         }
                         if (*pmsg) {    /* another error happen'd */
-                                TRACE_DEBUG(INFO, "An unexpected error occurred (%s), discarding a message:", strerror(ret));
-                                fd_msg_dump_walk(INFO, *pmsg);
+                                fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
                                 CHECK_FCT_DO( fd_msg_free(*pmsg), /* continue */);
                                 *pmsg = NULL;
@@ -522 +520 @@
                                 
                                 if (!is_req) {
-                                        TRACE_DEBUG(INFO, "Received an answer to a localy issued query, but no handler processed this answer!");
-                                        fd_msg_dump_walk(INFO, *pmsg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
                                         fd_msg_free(*pmsg);
                                         *pmsg = NULL;
@@ -748 +745 @@
                 for (   li = (is_req ? rt_fwd_list.next : rt_fwd_list.prev) ; *pmsg && (li != &rt_fwd_list) ; li = (is_req ? li->next : li->prev) ) {
                         struct rt_hdl * rh = (struct rt_hdl *)li;
+                        int ret;
 
                         if (is_req && (rh->dir > RT_FWD_ALL))
@@ -756 +754 @@
                         /* Ok, call this cb */
                         TRACE_DEBUG(ANNOYING, "Calling next FWD callback on %p : %p", *pmsg, rh->rt_fwd_cb);
-                        CHECK_FCT_DO( (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
+                        CHECK_FCT_DO( ret = (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
                                 {
-                                        TRACE_DEBUG(INFO, "A FWD routing callback returned an error, message discarded.");
-                                        fd_msg_dump_walk(INFO, *pmsg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
                                         fd_msg_free(*pmsg);
                                         *pmsg = NULL;
@@ -817 +814 @@
                 fd_cpu_flush_cache();
                 if ((!peer) || (peer->p_hdr.info.runtime.pir_state != STATE_OPEN)) {
-                        TRACE_DEBUG(INFO, "Unable to forward answer message to peer '%s', deleted or not in OPEN state.", qry_src);
-                        fd_msg_dump_walk(INFO, *pmsg);
+                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
                         fd_msg_free(*pmsg);
                         *pmsg = NULL;
@@ -897 +893 @@
                         CHECK_FCT_DO( ret = (*rh->rt_out_cb)(rh->cbdata, *pmsg, candidates),
                                 {
-                                        TRACE_DEBUG(INFO, "An OUT routing callback returned an error (%s) ! Message discarded.", strerror(ret));
-                                        fd_msg_dump_walk(INFO, *pmsg);
+                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
                                         fd_msg_free(*pmsg);
                                         *pmsg = NULL;
@@ -947 +942 @@
         /* If the message has not been sent, return an error */
         if (*pmsg) {
-                TRACE_DEBUG(INFO, "Could not send the following message, replying with UNABLE_TO_DELIVER");
-                fd_msg_dump_walk(INFO, *pmsg);
+                fd_msg_log( FD_MSG_LOG_NODELIVER, *pmsg, "No suitable candidate to route the message to." );
                 return_error( pmsg, "DIAMETER_UNABLE_TO_DELIVER", "No suitable candidate to route the message to", NULL);
         }

libfdcore/server.c

@@ -143 +143 @@
         CHECK_FCT_DO( fd_msg_parse_rules( msg, fd_g_config->cnf_dict, NULL ), /* Parsing failed -- trace details ? */ goto cleanup );
         
-        fd_msg_dump_walk(FULL, msg);
-        
         /* Now check we received a CER */
         CHECK_FCT_DO( fd_msg_hdr ( msg, &hdr ), goto fatal_error );
@@ -164 +162 @@
         CHECK_POSIX_DO( pthread_mutex_unlock(&s->clients_mtx), goto fatal_error );
         
+        /* 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 */);
+        }
+        
         /* Destroy the connection object if present */
         if (c->conn)
@@ -170 +174 @@
         /* Cleanup the received buffer if any */
         free(buf);
-        
-        /* Cleanup the parsed message if any */
-        if (msg) {
-                CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
-        }
         
         /* Detach the thread, cleanup the client structure */

libfdproto/messages.c

@@ -793 +793 @@
 
 /* Dump a message to a specified file stream */
-static void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
+void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
 {
         msg_or_avp * ref = msg;
@@ -2263 +2263 @@
                         *action = DISP_ACT_ERROR;
                 } else {
-                        TRACE_DEBUG(INFO, "Received an answer to a local query with an unsupported application %d, discarding...",  (*msg)->msg_public.msg_appl);
-                        fd_msg_dump_walk(INFO, *msg);
+                        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);
                         fd_msg_free(*msg);
                         *msg = NULL;
@@ -2337 +2336 @@
         pthread_mutex_t lock;
         int             init;
+        struct dictionary *dict;        
 } ml_conf = { .lock = PTHREAD_MUTEX_INITIALIZER, .init = 0 };
 
-static void ml_conf_init(void) 
+void ml_conf_init(struct dictionary *dict) 
 {
         memset(&ml_conf.causes, 0, sizeof(ml_conf.causes));
         ml_conf.init = 1;
+        ml_conf.dict = dict;
 }
 
@@ -2357 +2358 @@
         CHECK_POSIX( pthread_mutex_lock(&ml_conf.lock) );
         if (!ml_conf.init) {
-                ml_conf_init();
+                ASSERT(0);
         }
         
@@ -2406 +2407 @@
         CHECK_POSIX_DO( pthread_mutex_lock(&ml_conf.lock), );
         if (!ml_conf.init) {
-                ml_conf_init();
+                ASSERT(0);
         }
         meth    = ml_conf.causes[cause].meth;
@@ -2420 +2421 @@
                 case FD_MSG_LOGTO_FILE:
                         TODO("Log to arg file");
+                        TODO("Log a note to debug stream");
                         break;
                 case FD_MSG_LOGTO_DIR:
                         TODO("Log to arg directory in a new file");
-                        break;
-        }
-        
-        /* Then dump the prefix message to this stream */
+                        TODO("Log a note to debug stream");
+                        break;
+        }
+        
+        /* For file methods, let's parse the message so it looks better */
+        if ((meth != FD_MSG_LOGTO_DEBUGONLY) && ml_conf.dict) {
+                CHECK_FCT_DO( fd_msg_parse_dict( msg, ml_conf.dict, NULL ), );
+        }
+        
+        /* Then dump the prefix message to this stream, & to debug stream */
         (void)pthread_mutex_lock(&fd_log_lock);
         pthread_cleanup_push(fd_cleanup_mutex_silent, &fd_log_lock);

tests/testcnx.c

@@ -642 +642 @@
                 CHECK( 0, fd_msg_avp_add( cer, MSG_BRW_LAST_CHILD, oh) );
 
-                #if 1
+                #if 0
                 /* For debug: dump the object */
                 fd_log_debug("Dumping CER\n");