Navigation


Changeset 688:8c3dc8584dab in freeDiameter


Ignore:
Timestamp:
Jan 19, 2011, 7:05:30 PM (11 years ago)
Author:
Sebastien Decugis <sdecugis@nict.go.jp>
Branch:
default
Phase:
public
Message:

Prepared capability for messages logging to separate files / folders

Files:
16 edited

Legend:

Unmodified
Added
Removed
  • doc/dbg_interactive.py.sample

    r649 r688  
    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/app_radgw/rgwx_acct.c

    r639 r688  
    12151215out:
    12161216        if (answer && *answer) {
    1217                 TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding...");
     1217                TRACE_DEBUG(INFO, "Received the following problematic STA message, discarding anyway...");
    12181218                fd_msg_dump_walk( INFO, *answer );
    12191219                fd_msg_free(*answer);
  • extensions/dbg_interactive/messages.i

    r662 r688  
    254254        }
    255255       
     256        /* Log to file (depending on config)  */
     257        void log ( enum fd_msg_log_cause cause, char * message ) {
     258                fd_msg_log( cause, $self, message );
     259        }
     260       
    256261        /* Model */
    257262        struct dict_object * model() {
  • include/freeDiameter/libfdproto.h

    r687 r688  
    20552055        FD_MSG_LOG_DROPPED = 0,  /* message has been dropped by the framework */
    20562056        FD_MSG_LOG_RECEIVED,     /* message received from the network */
    2057         FD_MSG_LOG_SENT          /* message sent to another peer */
    2058 };
    2059 #define FD_MSG_LOG_MAX FD_MSG_LOG_SENT
     2057        FD_MSG_LOG_SENT,         /* message sent to another peer */
     2058        FD_MSG_LOG_NODELIVER     /* message could not be delivered to any peer */
     2059};
     2060#define FD_MSG_LOG_MAX FD_MSG_LOG_NODELIVER
    20602061void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... );
    20612062
     
    20672068};
    20682069int fd_msg_log_config(enum fd_msg_log_cause cause, enum fd_msg_log_method method, const char * arg);
     2070void ml_conf_init(struct dictionary *dict);
    20692071
    20702072/*********************************************/
  • libfdcore/core.c

    r686 r688  
    195195        fd_g_config = &g_conf;
    196196        CHECK_FCT( fd_conf_init() );
     197       
     198        /* Initialize the message logging facility */
     199        ml_conf_init(fd_g_config->cnf_dict);
    197200
    198201        /* Add definitions of the base protocol */
  • libfdcore/messages.c

    r658 r688  
    313313                return ret;
    314314       
    315         fd_log_debug("The following message does not comply to the dictionary and/or rules (%s):\n", pei.pei_errcode);
    316         fd_msg_dump_walk(NONE, m);
     315        TRACE_DEBUG(INFO, "A message does not comply to the dictionary and/or rules (%s)", pei.pei_errcode);
     316        fd_msg_dump_walk(FULL, m);
    317317       
    318318        CHECK_FCT( fd_msg_hdr(m, &hdr) );
     
    364364               
    365365                /* Just discard */
     366                fd_msg_log( FD_MSG_LOG_DROPPED, m, "Answer not compliant to dictionary's ABNF (%s)", pei.pei_errcode  );
    366367                CHECK_FCT( fd_msg_free( m ) );
    367368                *msg = NULL;
  • libfdcore/p_ce.c

    r662 r688  
    598598        fd_cnx_destroy(recv_cnx);
    599599        if (*cer) {
     600                fd_msg_log(FD_MSG_LOG_DROPPED, *cer, "An error occurred while rejecting a CER.");
    600601                fd_msg_free(*cer);
    601602                *cer = NULL;
     
    665666        if (req || (peer->p_hdr.info.runtime.pir_state != STATE_WAITCEA)) {
    666667                if (*msg) {
    667                         fd_log_debug("Received CER/CEA message while in state '%s', discarded.\n", STATE_STR(peer->p_hdr.info.runtime.pir_state));
    668                         fd_msg_dump_walk(NONE, *msg);
     668                        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));
    669669                        CHECK_FCT_DO( fd_msg_free(*msg), /* continue */);
    670670                        *msg = NULL;
     
    911911cleanup:
    912912        if (msg) {
     913                fd_msg_log(FD_MSG_LOG_DROPPED, msg, "An error occurred while processing a CER.");
    913914                fd_msg_free(msg);
    914915        }
  • libfdcore/p_out.c

    r662 r688  
    6060        }
    6161       
    62         /* Log the message */
    63         if (TRACE_BOOL(FULL)) {
    64                 CHECK_FCT_DO(  fd_msg_update_length(*msg), /* continue */  );
    65                 TRACE_DEBUG(FULL, "Sending the following message on connection '%s':", fd_cnx_getid(cnx));
    66                 fd_msg_dump_walk(FULL, *msg);
    67         }
    68        
    6962        /* Create the message buffer */
    7063        CHECK_FCT(fd_msg_bufferize( *msg, &buf, &sz ));
    7164        pthread_cleanup_push( free, buf );
     65       
     66        /* Log the message */
     67        fd_msg_log( FD_MSG_LOG_SENT, *msg, "Sent to '%s'", fd_cnx_getid(cnx));
    7268       
    7369        /* Save a request before sending so that there is no race condition with the answer */
     
    9389        struct msg *msg = arg;
    9490        CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &msg),
    95                         CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */));
     91                {
     92                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "An error occurred while attempting to requeue this message during cancellation of the sending function");
     93                        CHECK_FCT_DO(fd_msg_free(msg), /* What can we do more? */);
     94                } );
    9695}
    9796
     
    112111        while (1) {
    113112                struct msg * msg;
     113                int ret;
    114114               
    115115                /* Retrieve next message to send */
     
    120120               
    121121                /* Send the message, log any error */
    122                 CHECK_FCT_DO( do_send(&msg, 0, peer->p_cnxctx, &peer->p_hbh, &peer->p_sr),
     122                CHECK_FCT_DO( ret = do_send(&msg, 0, peer->p_cnxctx, &peer->p_hbh, &peer->p_sr),
    123123                        {
    124124                                if (msg) {
    125                                         fd_log_debug("An error occurred while sending this message, it was lost:\n");
    126                                         fd_msg_dump_walk(NONE, msg);
     125                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
    127126                                        fd_msg_free(msg);
    128127                                }
     
    151150               
    152151        } else {
     152                int ret;
    153153                uint32_t *hbh = NULL;
    154154               
     
    161161
    162162                /* Do send the message */
    163                 CHECK_FCT_DO( do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
     163                CHECK_FCT_DO( ret = do_send(msg, flags, cnx, hbh, peer ? &peer->p_sr : NULL),
    164164                        {
    165165                                if (msg) {
    166                                         fd_log_debug("An error occurred while sending this message, it was lost:\n");
    167                                         fd_msg_dump_walk(NONE, *msg);
     166                                        fd_msg_log( FD_MSG_LOG_DROPPED, *msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
    168167                                        fd_msg_free(*msg);
    169168                                        *msg = NULL;
  • libfdcore/p_psm.c

    r662 r688  
    166166                        case FDEVP_CNX_INCOMING: {
    167167                                struct cnx_incoming * evd = ev->data;
     168                                fd_msg_log( FD_MSG_LOG_DROPPED, evd->cer, "Message discarded while cleaning peer state machine queue." );
    168169                                CHECK_FCT_DO( fd_msg_free(evd->cer), /* continue */);
    169170                                fd_cnx_destroy(evd->cnx);
     
    394395                        } );
    395396               
    396                 TRACE_DEBUG(FULL, "Received a message (%zdb) from '%s'", ev_sz, peer->p_hdr.info.pi_diamid);
    397                 if (TRACE_BOOL(FULL+1)) {
    398                         CHECK_FCT_DO( fd_msg_parse_dict( msg, fd_g_config->cnf_dict, NULL ), );
    399                         fd_msg_dump_walk(FULL, msg);
    400                 } else {
    401                         fd_msg_dump_one(FULL, msg);
    402                 }
     397                /* Log incoming message */
     398                fd_msg_log( FD_MSG_LOG_RECEIVED, msg, "Received %zdb from '%s'", ev_sz, peer->p_hdr.info.pi_diamid );
    403399       
    404400                /* Extract the header */
     
    411407                        CHECK_FCT_DO( fd_p_sr_fetch(&peer->p_sr, hdr->msg_hbhid, &req), goto psm_end );
    412408                        if (req == NULL) {
    413                                 fd_log_debug("Received a Diameter answer message with no corresponding sent request, discarding.\n");
    414                                 fd_msg_dump_walk(NONE, msg);
     409                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Answer received with no corresponding sent request." );
    415410                                fd_msg_free(msg);
    416411                                goto psm_loop;
     
    453448                                default:
    454449                                        /* In such case, just discard the message */
    455                                         fd_log_debug("Received a routable message while not in OPEN state from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
    456                                         fd_msg_dump_walk(NONE, msg);
     450                                        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 );
    457451                                        fd_msg_free(msg);
    458452                        }
     
    468462                                if (msg) {
    469463                                        /* Send the error back to the peer */
    470                                         CHECK_FCT_DO( fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED), /* In case of error the message has already been dumped */ );
     464                                        CHECK_FCT_DO( ret = fd_out_send(&msg, NULL, peer, FD_CNX_ORDERED), );
    471465                                        if (msg) {
     466                                                /* Only if an error occurred & the message was not saved / dumped */
     467                                                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: Problem while sending (%s)\n", strerror(ret) );
    472468                                                CHECK_FCT_DO( fd_msg_free(msg), goto psm_end);
    473469                                        }
     
    498494                        default:
    499495                                /* Unknown / unexpected / invalid message */
    500                                 fd_log_debug("Received an unknown local message from peer '%s', discarded.\n", peer->p_hdr.info.pi_diamid);
    501                                 fd_msg_dump_walk(NONE, msg);
     496                                TRACE_DEBUG(INFO, "Invalid non-routable command received: %u.", hdr->msg_code);
    502497                                if (hdr->msg_flags & CMD_FLAG_REQUEST) {
    503498                                        do {
     
    518513                                /* Cleanup the message if not done */
    519514                                if (msg) {
     515                                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received un-handled non-routable command from peer '%s'.", peer->p_hdr.info.pi_diamid );
    520516                                        CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
    521517                                        msg = NULL;
     
    525521                /* At this point the message must have been fully handled already */
    526522                if (msg) {
    527                         fd_log_debug("Internal error: unhandled message (discarded)!\n");
    528                         fd_msg_dump_walk(NONE, msg);
     523                        fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Internal error: unhandled message.", peer->p_hdr.info.pi_diamid );
    529524                        fd_msg_free(msg);
    530525                }
     
    602597                }
    603598                if (params->cer) {
     599                        fd_msg_log( FD_MSG_LOG_DROPPED, params->cer, "Internal error: this CER was not handled as expected." );
    604600                        CHECK_FCT_DO( fd_msg_free(params->cer), );
    605601                        params->cer = NULL;
  • libfdcore/p_sr.c

    r662 r688  
    109109        /* If the callback did not dispose of the message, do it now */
    110110        if (expired_req) {
     111                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.");
    111112                CHECK_FCT_DO( fd_msg_free(expired_req), /* ignore */ );
    112113        }
     
    296297                if (fd_msg_is_routable(sr->req)) {
    297298                        struct msg_hdr * hdr = NULL;
     299                        int ret;
    298300                       
    299301                        /* Set the 'T' flag */
     
    303305                       
    304306                        /* Requeue for sending to another peer */
    305                         CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &sr->req),
    306                                         CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */));
     307                        CHECK_FCT_DO( ret = fd_fifo_post(fd_g_outgoing, &sr->req),
     308                                {
     309                                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Internal error: error while requeuing during failover: %s", strerror(ret) );
     310                                        CHECK_FCT_DO(fd_msg_free(sr->req), /* What can we do more? */)
     311                                });
    307312                } else {
    308                         /* Just free the request... */
     313                        /* Just free the request. */
     314                        fd_msg_log( FD_MSG_LOG_DROPPED, sr->req, "Local message discarded during failover" );
    309315                        CHECK_FCT_DO(fd_msg_free(sr->req), /* Ignore */);
    310316                }
  • libfdcore/peers.c

    r662 r688  
    211211        while ( fd_fifo_tryget(peer->p_tosend, &m) == 0 ) {
    212212                CHECK_FCT_DO(fd_fifo_post(fd_g_outgoing, &m),
     213                        {
    213214                                /* fallback: destroy the message */
    214                                 CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */));
     215                                fd_msg_log(FD_MSG_LOG_DROPPED, m, "Internal error: unable to requeue this message during failover process");
     216                                CHECK_FCT_DO(fd_msg_free(m), /* What can we do more? */)
     217                        } );
    215218        }
    216219       
  • libfdcore/queues.c

    r686 r688  
    7474               
    7575                /* We got one! */
    76                 fd_log_debug("The following message is lost because the daemon is stopping:\n");
    77                 fd_msg_dump_walk(NONE, msg);
     76                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Message lost because framework is terminating." );
    7877                fd_msg_free(msg);
    7978        }
  • libfdcore/routing_dispatch.c

    r686 r688  
    409409
    410410                        if (!peer) {
    411                                 TRACE_DEBUG(INFO, "Unable to send error '%s' to deleted peer '%s' in reply to:", error_code, id);
    412                                 fd_msg_dump_walk(INFO, *pmsg);
     411                                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);
    413412                                fd_msg_free(*pmsg);
    414413                                *pmsg = NULL;
     
    467466                        }
    468467                        if (*pmsg) {    /* another error happen'd */
    469                                 TRACE_DEBUG(INFO, "An unexpected error occurred (%s), discarding a message:", strerror(ret));
    470                                 fd_msg_dump_walk(INFO, *pmsg);
     468                                fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "An unexpected error occurred while parsing the message (%s)", strerror(ret));
    471469                                CHECK_FCT_DO( fd_msg_free(*pmsg), /* continue */);
    472470                                *pmsg = NULL;
     
    522520                               
    523521                                if (!is_req) {
    524                                         TRACE_DEBUG(INFO, "Received an answer to a localy issued query, but no handler processed this answer!");
    525                                         fd_msg_dump_walk(INFO, *pmsg);
     522                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg,  "Internal error: Answer received to locally issued request, but not handled by any handler.");
    526523                                        fd_msg_free(*pmsg);
    527524                                        *pmsg = NULL;
     
    748745                for (   li = (is_req ? rt_fwd_list.next : rt_fwd_list.prev) ; *pmsg && (li != &rt_fwd_list) ; li = (is_req ? li->next : li->prev) ) {
    749746                        struct rt_hdl * rh = (struct rt_hdl *)li;
     747                        int ret;
    750748
    751749                        if (is_req && (rh->dir > RT_FWD_ALL))
     
    756754                        /* Ok, call this cb */
    757755                        TRACE_DEBUG(ANNOYING, "Calling next FWD callback on %p : %p", *pmsg, rh->rt_fwd_cb);
    758                         CHECK_FCT_DO( (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
     756                        CHECK_FCT_DO( ret = (*rh->rt_fwd_cb)(rh->cbdata, pmsg),
    759757                                {
    760                                         TRACE_DEBUG(INFO, "A FWD routing callback returned an error, message discarded.");
    761                                         fd_msg_dump_walk(INFO, *pmsg);
     758                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: a FWD routing callback returned an error (%s)", strerror(ret));
    762759                                        fd_msg_free(*pmsg);
    763760                                        *pmsg = NULL;
     
    817814                fd_cpu_flush_cache();
    818815                if ((!peer) || (peer->p_hdr.info.runtime.pir_state != STATE_OPEN)) {
    819                         TRACE_DEBUG(INFO, "Unable to forward answer message to peer '%s', deleted or not in OPEN state.", qry_src);
    820                         fd_msg_dump_walk(INFO, *pmsg);
     816                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Unable to forward answer to deleted / closed peer '%s'.", qry_src);
    821817                        fd_msg_free(*pmsg);
    822818                        *pmsg = NULL;
     
    897893                        CHECK_FCT_DO( ret = (*rh->rt_out_cb)(rh->cbdata, *pmsg, candidates),
    898894                                {
    899                                         TRACE_DEBUG(INFO, "An OUT routing callback returned an error (%s) ! Message discarded.", strerror(ret));
    900                                         fd_msg_dump_walk(INFO, *pmsg);
     895                                        fd_msg_log( FD_MSG_LOG_DROPPED, *pmsg, "Internal error: an OUT routing callback returned an error (%s)", strerror(ret));
    901896                                        fd_msg_free(*pmsg);
    902897                                        *pmsg = NULL;
     
    947942        /* If the message has not been sent, return an error */
    948943        if (*pmsg) {
    949                 TRACE_DEBUG(INFO, "Could not send the following message, replying with UNABLE_TO_DELIVER");
    950                 fd_msg_dump_walk(INFO, *pmsg);
     944                fd_msg_log( FD_MSG_LOG_NODELIVER, *pmsg, "No suitable candidate to route the message to." );
    951945                return_error( pmsg, "DIAMETER_UNABLE_TO_DELIVER", "No suitable candidate to route the message to", NULL);
    952946        }
  • libfdcore/server.c

    r686 r688  
    143143        CHECK_FCT_DO( fd_msg_parse_rules( msg, fd_g_config->cnf_dict, NULL ), /* Parsing failed -- trace details ? */ goto cleanup );
    144144       
    145         fd_msg_dump_walk(FULL, msg);
    146        
    147145        /* Now check we received a CER */
    148146        CHECK_FCT_DO( fd_msg_hdr ( msg, &hdr ), goto fatal_error );
     
    164162        CHECK_POSIX_DO( pthread_mutex_unlock(&s->clients_mtx), goto fatal_error );
    165163       
     164        /* Cleanup the parsed message if any */
     165        if (msg) {
     166                fd_msg_log( FD_MSG_LOG_DROPPED, msg, "Received invalid/unexpected message from connecting client '%s'", fd_cnx_getid(c->conn) );
     167                CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
     168        }
     169       
    166170        /* Destroy the connection object if present */
    167171        if (c->conn)
     
    170174        /* Cleanup the received buffer if any */
    171175        free(buf);
    172        
    173         /* Cleanup the parsed message if any */
    174         if (msg) {
    175                 CHECK_FCT_DO( fd_msg_free(msg), /* continue */);
    176         }
    177176       
    178177        /* Detach the thread, cleanup the client structure */
  • libfdproto/messages.c

    r687 r688  
    793793
    794794/* Dump a message to a specified file stream */
    795 static void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
     795void fd_msg_dump_fstr ( struct msg * msg, FILE * fstr )
    796796{
    797797        msg_or_avp * ref = msg;
     
    22632263                        *action = DISP_ACT_ERROR;
    22642264                } else {
    2265                         TRACE_DEBUG(INFO, "Received an answer to a local query with an unsupported application %d, discarding...",  (*msg)->msg_public.msg_appl);
    2266                         fd_msg_dump_walk(INFO, *msg);
     2265                        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);
    22672266                        fd_msg_free(*msg);
    22682267                        *msg = NULL;
     
    23372336        pthread_mutex_t lock;
    23382337        int             init;
     2338        struct dictionary *dict;       
    23392339} ml_conf = { .lock = PTHREAD_MUTEX_INITIALIZER, .init = 0 };
    23402340
    2341 static void ml_conf_init(void)
     2341void ml_conf_init(struct dictionary *dict)
    23422342{
    23432343        memset(&ml_conf.causes, 0, sizeof(ml_conf.causes));
    23442344        ml_conf.init = 1;
     2345        ml_conf.dict = dict;
    23452346}
    23462347
     
    23572358        CHECK_POSIX( pthread_mutex_lock(&ml_conf.lock) );
    23582359        if (!ml_conf.init) {
    2359                 ml_conf_init();
     2360                ASSERT(0);
    23602361        }
    23612362       
     
    24062407        CHECK_POSIX_DO( pthread_mutex_lock(&ml_conf.lock), );
    24072408        if (!ml_conf.init) {
    2408                 ml_conf_init();
     2409                ASSERT(0);
    24092410        }
    24102411        meth    = ml_conf.causes[cause].meth;
     
    24202421                case FD_MSG_LOGTO_FILE:
    24212422                        TODO("Log to arg file");
     2423                        TODO("Log a note to debug stream");
    24222424                        break;
    24232425                case FD_MSG_LOGTO_DIR:
    24242426                        TODO("Log to arg directory in a new file");
    2425                         break;
    2426         }
    2427        
    2428         /* Then dump the prefix message to this stream */
     2427                        TODO("Log a note to debug stream");
     2428                        break;
     2429        }
     2430       
     2431        /* For file methods, let's parse the message so it looks better */
     2432        if ((meth != FD_MSG_LOGTO_DEBUGONLY) && ml_conf.dict) {
     2433                CHECK_FCT_DO( fd_msg_parse_dict( msg, ml_conf.dict, NULL ), );
     2434        }
     2435       
     2436        /* Then dump the prefix message to this stream, & to debug stream */
    24292437        (void)pthread_mutex_lock(&fd_log_lock);
    24302438        pthread_cleanup_push(fd_cleanup_mutex_silent, &fd_log_lock);
  • tests/testcnx.c

    r662 r688  
    642642                CHECK( 0, fd_msg_avp_add( cer, MSG_BRW_LAST_CHILD, oh) );
    643643
    644                 #if 1
     644                #if 0
    645645                /* For debug: dump the object */
    646646                fd_log_debug("Dumping CER\n");
Note: See TracChangeset for help on using the changeset viewer.