2017-08-05 05:23:37 +00:00
|
|
|
#define TRACE_MODULE _fd_logger
|
2017-08-02 06:11:08 +00:00
|
|
|
|
|
|
|
#include "core_debug.h"
|
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
#include "fd_context.h"
|
|
|
|
#include "fd_logger.h"
|
2017-08-02 06:11:08 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
static struct fd_hook_hdl *logger_hdl = NULL;
|
2017-08-02 06:11:08 +00:00
|
|
|
static char * buf = NULL;
|
|
|
|
static size_t len;
|
|
|
|
static pthread_mutex_t mtx = PTHREAD_MUTEX_INITIALIZER;
|
2017-08-05 05:23:37 +00:00
|
|
|
static pthread_t fd_stats_th = (pthread_t)NULL;
|
2017-08-02 06:11:08 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
static fd_logger_user_handler user_handler = NULL;
|
|
|
|
|
|
|
|
static void fd_logger_cb_tree(enum fd_hook_type type, struct msg * msg,
|
|
|
|
struct peer_hdr * peer, void * other, struct fd_hook_permsgdata *pmd,
|
|
|
|
void * regdata);
|
|
|
|
static void * fd_stats_worker(void * arg);
|
|
|
|
|
|
|
|
int fd_logger_init()
|
|
|
|
{
|
|
|
|
uint32_t mask_errors, mask_sndrcv, mask_routing, mask_peers;
|
|
|
|
uint32_t mask_tree;
|
|
|
|
|
|
|
|
mask_errors = HOOK_MASK( HOOK_MESSAGE_FAILOVER, HOOK_MESSAGE_PARSING_ERROR,
|
|
|
|
HOOK_MESSAGE_ROUTING_ERROR, HOOK_MESSAGE_DROPPED );
|
|
|
|
mask_sndrcv = HOOK_MASK( HOOK_MESSAGE_RECEIVED, HOOK_MESSAGE_SENT );
|
|
|
|
mask_routing= HOOK_MASK( HOOK_MESSAGE_LOCAL,
|
|
|
|
HOOK_MESSAGE_ROUTING_FORWARD, HOOK_MESSAGE_ROUTING_LOCAL );
|
|
|
|
mask_peers = HOOK_MASK( HOOK_PEER_CONNECT_FAILED,
|
|
|
|
HOOK_PEER_CONNECT_SUCCESS );
|
|
|
|
|
|
|
|
mask_tree = mask_errors;
|
|
|
|
mask_tree |= mask_sndrcv;
|
|
|
|
mask_tree |= mask_routing;
|
|
|
|
mask_tree |= mask_peers;
|
|
|
|
|
|
|
|
CHECK_FCT( fd_hook_register(
|
|
|
|
mask_tree, fd_logger_cb_tree, NULL, NULL, &logger_hdl) );
|
|
|
|
|
|
|
|
CHECK_POSIX( pthread_mutex_init(&fd_self()->stats_lock, NULL) );
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
void fd_logger_final()
|
|
|
|
{
|
|
|
|
CHECK_FCT_DO( fd_thr_term(&fd_stats_th), );
|
|
|
|
CHECK_POSIX_DO( pthread_mutex_destroy(&fd_self()->stats_lock), );
|
|
|
|
|
|
|
|
if (logger_hdl) { CHECK_FCT_DO( fd_hook_unregister( logger_hdl ), ); }
|
|
|
|
}
|
|
|
|
|
|
|
|
int fd_logger_stats_start()
|
|
|
|
{
|
|
|
|
/* Start the statistics thread */
|
|
|
|
CHECK_POSIX( pthread_create(&fd_stats_th, NULL, fd_stats_worker, NULL) );
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
void fd_logger_register(fd_logger_user_handler instance)
|
|
|
|
{
|
|
|
|
user_handler = instance;
|
|
|
|
}
|
|
|
|
|
|
|
|
void fd_logger_unregister(void)
|
|
|
|
{
|
|
|
|
user_handler = NULL;
|
|
|
|
}
|
2017-08-02 10:15:30 +00:00
|
|
|
|
2017-08-02 06:11:08 +00:00
|
|
|
/* The callback called when messages are received and sent */
|
2017-08-05 05:23:37 +00:00
|
|
|
static void fd_logger_cb_tree(enum fd_hook_type type, struct msg * msg,
|
2017-08-02 10:15:30 +00:00
|
|
|
struct peer_hdr * peer, void * other, struct fd_hook_permsgdata *pmd,
|
|
|
|
void * regdata)
|
2017-08-02 06:11:08 +00:00
|
|
|
{
|
|
|
|
char * peer_name = peer ? peer->info.pi_diamid : "<unknown peer>";
|
|
|
|
|
|
|
|
CHECK_POSIX_DO( pthread_mutex_lock(&mtx), );
|
2017-08-02 10:15:30 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
if (user_handler)
|
|
|
|
user_handler(type, msg, peer, other, pmd, regdata);
|
2017-08-04 12:29:49 +00:00
|
|
|
|
2017-08-02 06:11:08 +00:00
|
|
|
if (msg) {
|
|
|
|
CHECK_MALLOC_DO( fd_msg_dump_treeview(&buf, &len, NULL, msg, fd_g_config->cnf_dict, (type == HOOK_MESSAGE_PARSING_ERROR) ? 0 : 1, 1),
|
|
|
|
{ LOG_E("Error while dumping a message"); pthread_mutex_unlock(&mtx); return; } );
|
|
|
|
}
|
|
|
|
|
|
|
|
switch (type) {
|
|
|
|
/* errors */
|
|
|
|
case HOOK_MESSAGE_FAILOVER:
|
|
|
|
LOG_E("FAILOVER from '%s':", peer_name);
|
|
|
|
LOG_SPLIT(FD_LOG_ERROR, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_PARSING_ERROR:
|
|
|
|
if (msg) {
|
|
|
|
DiamId_t id = NULL;
|
|
|
|
if (fd_msg_source_get( msg, &id, NULL ))
|
|
|
|
id = (DiamId_t)"<error getting source>";
|
|
|
|
if (!id)
|
|
|
|
id = (DiamId_t)"<local>";
|
|
|
|
LOG_E("PARSING ERROR: '%s' from '%s': ", (char *)other, (char *)id);
|
|
|
|
LOG_SPLIT(FD_LOG_ERROR, " ", buf, NULL);
|
|
|
|
} else {
|
|
|
|
struct fd_cnx_rcvdata *rcv_data = other;
|
|
|
|
CHECK_MALLOC_DO(fd_dump_extend_hexdump(&buf, &len, NULL, rcv_data->buffer, rcv_data->length, 0, 0), break);
|
|
|
|
LOG_E("PARSING ERROR: %zdB msg from '%s': %s", rcv_data->length, peer_name, buf);
|
|
|
|
}
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_ROUTING_ERROR:
|
|
|
|
LOG_E("ROUTING ERROR '%s' for: ", (char *)other);
|
|
|
|
LOG_SPLIT(FD_LOG_ERROR, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_DROPPED:
|
|
|
|
LOG_E("DROPPED '%s'", (char *)other);
|
|
|
|
LOG_SPLIT(FD_LOG_ERROR, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
|
|
|
|
/* send receive */
|
|
|
|
case HOOK_MESSAGE_RECEIVED:
|
|
|
|
LOG_N("RCV from '%s':", peer_name);
|
|
|
|
LOG_SPLIT(FD_LOG_DEBUG, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_SENT:
|
|
|
|
LOG_N("SND to '%s':", peer_name);
|
|
|
|
LOG_SPLIT(FD_LOG_DEBUG, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
|
|
|
|
/* routing */
|
|
|
|
case HOOK_MESSAGE_LOCAL:
|
|
|
|
LOG_N("ISSUED:");
|
|
|
|
LOG_SPLIT(FD_LOG_DEBUG, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_ROUTING_FORWARD:
|
|
|
|
LOG_D("FORWARDING: %s", buf);
|
|
|
|
LOG_SPLIT(FD_LOG_DEBUG, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
case HOOK_MESSAGE_ROUTING_LOCAL:
|
|
|
|
LOG_D("DISPATCHING: %s", buf);
|
|
|
|
LOG_SPLIT(FD_LOG_DEBUG, " ", buf, NULL);
|
|
|
|
break;
|
|
|
|
|
|
|
|
/* peers */
|
|
|
|
case HOOK_PEER_CONNECT_FAILED:
|
|
|
|
LOG_N("CONNECT FAILED to %s: %s", peer_name, (char *)other);
|
|
|
|
break;
|
|
|
|
case HOOK_PEER_CONNECT_SUCCESS:
|
|
|
|
{
|
|
|
|
char protobuf[40];
|
|
|
|
if (peer) {
|
|
|
|
CHECK_FCT_DO(fd_peer_cnx_proto_info(peer, protobuf, sizeof(protobuf)), break );
|
|
|
|
} else {
|
|
|
|
protobuf[0] = '-';
|
|
|
|
protobuf[1] = '\0';
|
|
|
|
}
|
|
|
|
d_info("CONNECTED TO '%s' (%s):", peer_name, protobuf);
|
|
|
|
LOG_N("CONNECTED TO '%s' (%s):", peer_name, protobuf);
|
|
|
|
LOG_SPLIT(FD_LOG_NOTICE, " ", buf, NULL);
|
|
|
|
}
|
|
|
|
break;
|
|
|
|
|
|
|
|
/* Not handled */
|
|
|
|
case HOOK_DATA_RECEIVED:
|
|
|
|
break;
|
|
|
|
}
|
|
|
|
|
|
|
|
CHECK_POSIX_DO( pthread_mutex_unlock(&mtx), );
|
|
|
|
}
|
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
/* Function to display statistics periodically */
|
|
|
|
static void * fd_stats_worker(void * arg)
|
2017-08-02 06:11:08 +00:00
|
|
|
{
|
2017-08-05 05:23:37 +00:00
|
|
|
struct timespec start, now;
|
|
|
|
struct fd_stats copy;
|
2017-08-02 06:11:08 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
/* Get the start time */
|
|
|
|
CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &start), );
|
2017-08-02 06:11:08 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
/* Now, loop until canceled */
|
|
|
|
while (1) {
|
|
|
|
/* Display statistics every XX seconds */
|
|
|
|
sleep(fd_self()->duration);
|
|
|
|
|
|
|
|
/* Now, get the current stats */
|
|
|
|
CHECK_POSIX_DO( pthread_mutex_lock(&fd_self()->stats_lock), );
|
|
|
|
memcpy(©, &fd_self()->stats, sizeof(struct fd_stats));
|
|
|
|
CHECK_POSIX_DO( pthread_mutex_unlock(&fd_self()->stats_lock), );
|
|
|
|
|
|
|
|
/* Get the current execution time */
|
|
|
|
CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &now), );
|
|
|
|
|
|
|
|
/* Now, display everything */
|
|
|
|
d_trace(3, "------- fd statistics ---------\n");
|
|
|
|
if (now.tv_nsec >= start.tv_nsec)
|
|
|
|
{
|
|
|
|
d_trace(3, " Executing for: %d.%06ld sec\n",
|
|
|
|
(int)(now.tv_sec - start.tv_sec),
|
|
|
|
(long)(now.tv_nsec - start.tv_nsec) / 1000);
|
|
|
|
}
|
|
|
|
else
|
|
|
|
{
|
|
|
|
d_trace(3, " Executing for: %d.%06ld sec\n",
|
|
|
|
(int)(now.tv_sec - 1 - start.tv_sec),
|
|
|
|
(long)(now.tv_nsec + 1000000000 - start.tv_nsec) / 1000);
|
|
|
|
}
|
|
|
|
|
|
|
|
if (fd_self()->mode & FD_MODE_SERVER) {
|
|
|
|
d_trace(3, " Server: %llu message(s) echoed\n",
|
|
|
|
copy.nb_echoed);
|
|
|
|
}
|
|
|
|
if (fd_self()->mode & FD_MODE_CLIENT) {
|
|
|
|
d_trace(3, " Client:\n");
|
|
|
|
d_trace(3, " %llu message(s) sent\n", copy.nb_sent);
|
|
|
|
d_trace(3, " %llu error(s) received\n", copy.nb_errs);
|
|
|
|
d_trace(3, " %llu answer(s) received\n", copy.nb_recv);
|
|
|
|
d_trace(3, " fastest: %ld.%06ld sec.\n",
|
|
|
|
copy.shortest / 1000000, copy.shortest % 1000000);
|
|
|
|
d_trace(3, " slowest: %ld.%06ld sec.\n",
|
|
|
|
copy.longest / 1000000, copy.longest % 1000000);
|
|
|
|
d_trace(3, " Average: %ld.%06ld sec.\n",
|
|
|
|
copy.avg / 1000000, copy.avg % 1000000);
|
|
|
|
}
|
|
|
|
d_trace(3, "-------------------------------------\n");
|
|
|
|
}
|
2017-08-02 06:11:08 +00:00
|
|
|
|
2017-08-05 05:23:37 +00:00
|
|
|
return NULL; /* never called */
|
2017-08-02 06:11:08 +00:00
|
|
|
}
|
|
|
|
|