Logger fix

This commit is contained in:
mannol 2015-01-10 23:09:51 +01:00
parent dd51e03857
commit ad67259535
8 changed files with 277 additions and 191 deletions

View File

@ -82,37 +82,40 @@ AC_ARG_ENABLE([randombytes-stir],
]
)
AC_ARG_ENABLE([logging],
[AC_HELP_STRING([--enable-logging], [enable logging (default: auto)]) ],
AC_ARG_ENABLE([log],
[AC_HELP_STRING([--enable-log], [enable logging (default: auto)]) ],
[
if test "x$enableval" = "xyes"; then
LOGGING="yes"
AC_DEFINE([LOGGING], [], [If logging enabled])
AC_DEFINE([LOGGER_LEVEL], [DEBUG], [LoggerLevel value])
AC_DEFINE([LOGGER_LEVEL], [LOG_DEBUG], [LOG_LEVEL value])
AC_DEFINE_UNQUOTED([LOGGER_OUTPUT_FILE], ["$LOGGING_OUTNAM"], [Output of logger])
fi
]
)
AC_ARG_WITH(logger-level,
AC_HELP_STRING([--with-logger-level=LEVEL],
[Logger levels: INFO; DEBUG; WARNING; ERROR ]),
AC_ARG_WITH(log-level,
AC_HELP_STRING([--with-log-level=LEVEL],
[Logger levels: TRACE; DEBUG; INFO; WARNING; ERROR ]),
[
if test "x$LOGGING" = "xno"; then
AC_MSG_WARN([Logging disabled!])
else
if test "x$withval" = "xINFO"; then
AC_DEFINE([LOGGER_LEVEL], [INFO], [LoggerLevel value])
if test "x$withval" = "xTRACE"; then
AC_DEFINE([LOGGER_LEVEL], [LOG_TRACE], [LOG_LEVEL value])
elif test "x$withval" = "xDEBUG"; then
AC_DEFINE([LOGGER_LEVEL], [DEBUG], [LoggerLevel value])
AC_DEFINE([LOGGER_LEVEL], [LOG_DEBUG], [LOG_LEVEL value])
elif test "x$withval" = "xINFO"; then
AC_DEFINE([LOGGER_LEVEL], [LOG_INFO], [LOG_LEVEL value])
elif test "x$withval" = "xWARNING"; then
AC_DEFINE([LOGGER_LEVEL], [WARNING], [LoggerLevel value])
AC_DEFINE([LOGGER_LEVEL], [LOG_WARNING], [LOG_LEVEL value])
elif test "x$withval" = "xERROR"; then
AC_DEFINE([LOGGER_LEVEL], [ERROR], [LoggerLevel value])
AC_DEFINE([LOGGER_LEVEL], [LOG_ERROR], [LOG_LEVEL value])
else
AC_MSG_WARN([Invalid logger level: $withval. Using default 'DEBUG'])
fi
@ -120,8 +123,8 @@ AC_ARG_WITH(logger-level,
]
)
AC_ARG_WITH(logger-path,
AC_HELP_STRING([--with-logger-path=DIR],
AC_ARG_WITH(log-path,
AC_HELP_STRING([--with-log-path=DIR],
[Path of logger output]),
[
if test "x$LOGGING" = "xno"; then

View File

@ -330,11 +330,11 @@ static int client_or_ip_port_in_list(Client_data *list, uint16_t length, const u
if (ip_port.ip.family == AF_INET) {
LOGGER_SCOPE( if (!ipport_equal(&list[i].assoc4.ip_port, &ip_port)) {
LOGGER_INFO("coipil[%u]: switching ipv4 from %s:%u to %s:%u", i,
LOGGER_TRACE("coipil[%u]: switching ipv4 from %s:%u to %s:%u", i,
ip_ntoa(&list[i].assoc4.ip_port.ip), ntohs(list[i].assoc4.ip_port.port),
ip_ntoa(&ip_port.ip), ntohs(ip_port.port));
}
);
}
);
if (LAN_ip(list[i].assoc4.ip_port.ip) != 0 && LAN_ip(ip_port.ip) == 0)
return 1;
@ -344,11 +344,11 @@ static int client_or_ip_port_in_list(Client_data *list, uint16_t length, const u
} else if (ip_port.ip.family == AF_INET6) {
LOGGER_SCOPE( if (!ipport_equal(&list[i].assoc4.ip_port, &ip_port)) {
LOGGER_INFO("coipil[%u]: switching ipv6 from %s:%u to %s:%u", i,
LOGGER_TRACE("coipil[%u]: switching ipv6 from %s:%u to %s:%u", i,
ip_ntoa(&list[i].assoc6.ip_port.ip), ntohs(list[i].assoc6.ip_port.port),
ip_ntoa(&ip_port.ip), ntohs(ip_port.port));
}
);
}
);
if (LAN_ip(list[i].assoc6.ip_port.ip) != 0 && LAN_ip(ip_port.ip) == 0)
return 1;

View File

@ -2424,7 +2424,7 @@ void do_messenger(Messenger *m)
if (last_pinged > 999)
last_pinged = 999;
LOGGER_INFO("C[%2u] %s:%u [%3u] %s",
LOGGER_TRACE("C[%2u] %s:%u [%3u] %s",
client, ip_ntoa(&assoc->ip_port.ip), ntohs(assoc->ip_port.port),
last_pinged, ID2String(cptr->client_id));
}
@ -2457,7 +2457,7 @@ void do_messenger(Messenger *m)
dht2m[m2dht[friend]] = friend;
if (m->numfriends != m->dht->num_friends) {
LOGGER_INFO("Friend num in DHT %u != friend num in msger %u\n", m->dht->num_friends, m->numfriends);
LOGGER_TRACE("Friend num in DHT %u != friend num in msger %u\n", m->dht->num_friends, m->numfriends);
}
uint32_t ping_lastrecv;
@ -2478,11 +2478,11 @@ void do_messenger(Messenger *m)
if (ping_lastrecv > 999)
ping_lastrecv = 999;
LOGGER_INFO("F[%2u:%2u] <%s> [%03u] %s",
LOGGER_TRACE("F[%2u:%2u] <%s> [%03u] %s",
dht2m[friend], friend, msgfptr->name,
ping_lastrecv, ID2String(msgfptr->client_id));
} else {
LOGGER_INFO("F[--:%2u] %s", friend, ID2String(dhtfptr->client_id));
LOGGER_TRACE("F[--:%2u] %s", friend, ID2String(dhtfptr->client_id));
}
for (client = 0; client < MAX_FRIEND_CLIENTS; client++) {
@ -2497,7 +2497,7 @@ void do_messenger(Messenger *m)
if (last_pinged > 999)
last_pinged = 999;
LOGGER_INFO("F[%2u] => C[%2u] %s:%u [%3u] %s",
LOGGER_TRACE("F[%2u] => C[%2u] %s:%u [%3u] %s",
friend, client, ip_ntoa(&assoc->ip_port.ip),
ntohs(assoc->ip_port.port), last_pinged,
ID2String(cptr->client_id));

View File

@ -996,11 +996,11 @@ static char *idpart2str(uint8_t *id, size_t len)
void Assoc_status(const Assoc *assoc)
{
if (!assoc) {
LOGGER_INFO("Assoc status: no assoc");
LOGGER_TRACE("Assoc status: no assoc");
return;
}
LOGGER_INFO("[b:p] hash => [id...] used, seen, heard");
LOGGER_TRACE("[b:p] hash => [id...] used, seen, heard");
size_t bid, cid, total = 0;
@ -1013,7 +1013,7 @@ void Assoc_status(const Assoc *assoc)
if (entry->hash) {
total++;
LOGGER_INFO("[%3i:%3i] %08x => [%s...] %i, %i(%c), %i(%c)\n",
LOGGER_TRACE("[%3i:%3i] %08x => [%s...] %i, %i(%c), %i(%c)\n",
(int)bid, (int)cid, entry->hash, idpart2str(entry->client.client_id, 8),
entry->used_at ? (int)(unix_time() - entry->used_at) : 0,
entry->seen_at ? (int)(unix_time() - entry->seen_at) : 0,
@ -1025,7 +1025,7 @@ void Assoc_status(const Assoc *assoc)
}
if (total) {
LOGGER_INFO("Total: %i entries, table usage %i%%.\n", (int)total,
LOGGER_TRACE("Total: %i entries, table usage %i%%.\n", (int)total,
(int)(total * 100 / (assoc->candidates_bucket_count * assoc->candidates_bucket_size)));
}
}

View File

@ -1,6 +1,4 @@
/* logger.c
*
* Wrapping logger functions in nice macros
*
* Copyright (C) 2013 Tox project All Rights Reserved.
*
@ -26,10 +24,7 @@
#endif /* HAVE_CONFIG_H */
#include "logger.h"
#ifdef LOGGING
#include "network.h" /* for time */
#include "crypto_core.h" /* for random_int() */
#include <stdio.h>
#include <errno.h>
@ -37,121 +32,201 @@
#include <stdarg.h>
#include <inttypes.h>
#include <time.h>
#include <pthread.h>
#if defined(_WIN32) || defined(__WIN32__) || defined (WIN32)
#define strerror_r(errno,buf,len) strerror_s(buf,len,errno)
# define getpid() ((unsigned) GetCurrentProcessId())
# define SFILE(FILE__M) (strrchr(FILE__M, '\\') ? strrchr(FILE__M, '\\') + 1 : FILE__M)
#else
# define SFILE(FILE__M) (strrchr(FILE__M, '/') ? strrchr(FILE__M, '/') + 1 : FILE__M)
#endif
static struct logger_config {
typedef struct logger {
FILE *log_file;
LoggerLevel level;
LOG_LEVEL level;
uint64_t start_time; /* Time when lib loaded */
}
logger = {
NULL,
DEBUG,
0
char* id;
/* Allocate these once */
char* tstr;
char* posstr;
char* msg;
/* For thread synchronisation */
pthread_mutex_t mutex[1];
} logger;
logger* global = NULL;
const char* LOG_LEVEL_STR [] = {
[LOG_TRACE] = "TRACE",
[LOG_DEBUG] = "DEBUG",
[LOG_INFO] = "INFO" ,
[LOG_WARNING] = "WARN" ,
[LOG_ERROR] = "ERROR",
};
void __attribute__((destructor)) terminate_logger()
{
if ( !logger.log_file ) return;
time_t tim = time(NULL);
logger_write(ERROR, "\n============== Closing logger [%u] ==============\n"
"Time: %s", logger_get_pid(), asctime(localtime(&tim)));
fclose(logger.log_file);
}
unsigned logger_get_pid()
{
return
#if defined(_WIN32) || defined(__WIN32__) || defined (WIN32)
GetCurrentProcessId();
#else
getpid();
#endif
}
const char *logger_stringify_level(LoggerLevel level)
{
static const char *strings [] = {
"INFO",
"DEBUG",
"WARN",
"ERROR"
};
return strings[level];
}
int logger_init(const char *file_name, LoggerLevel level)
{
if (logger.log_file) {
fprintf(stderr, "Error opening logger name: %s with level %d: file already opened!\n",
file_name, level);
return -1;
}
logger.log_file = fopen(file_name, "ab");
if (logger.log_file == NULL) {
fprintf(stderr, "Error opening logger file: %s; info: %s\n", file_name, strerror(errno));
return -1;
}
logger.level = level;
logger.start_time = current_time_monotonic();
time_t tim = time(NULL);
logger_write(ERROR, "\n============== Starting logger [%u] ==============\n"
"Time: %s", logger_get_pid(), asctime(localtime(&tim)));
return 0;
}
void logger_write (LoggerLevel level, const char *format, ...)
{
if (logger.log_file == NULL) {
/*fprintf(stderr, "Logger file is NULL!\n");*/
return;
}
if (logger.level > level) return; /* Don't print some levels xuh */
va_list _arg;
va_start (_arg, format);
vfprintf (logger.log_file, format, _arg);
va_end (_arg);
fflush(logger.log_file);
}
char *logger_timestr(char *dest, size_t max_size)
char* strtime(char* dest, size_t max_len)
{
time_t timer;
struct tm *tm_info;
time(&timer);
tm_info = localtime(&timer);
strftime(dest, max_size, "%m:%d %H:%M:%S", tm_info);
strftime(dest, max_len, "%m:%d %H:%M:%S", tm_info);
return dest;
/*uint64_t diff = (current_time_monotonic() - logger.start_time); /* ms * /
snprintf(dest, max_size, "%"PRIu64"", diff);
return dest; */
}
char *logger_posstr (char *dest, size_t max_size, const char *file, int line)
/**
* Public Functions
*/
logger* logger_new (const char *file_name, LOG_LEVEL level, const char* id)
{
snprintf(dest, max_size, "%s:%d", file, line);
return dest;
#ifndef LOGGING /* Disabled */
return NULL;
#endif
logger* retu = calloc(1, sizeof(logger));
if (!retu)
return NULL;
if ( pthread_mutex_init(retu->mutex, NULL) != 0 ) {
free(retu);
return NULL;
}
if (!(retu->log_file = fopen(file_name, "ab"))) {
fprintf(stderr, "Error opening logger file: %s; info: %s\n", file_name, strerror(errno));
free(retu);
pthread_mutex_destroy(retu->mutex);
return NULL;
}
if (!(retu->tstr = calloc(16, sizeof (char))) ||
!(retu->posstr = calloc(300, sizeof (char))) ||
!(retu->msg = calloc(4096, sizeof (char))) )
goto ERROR;
if (id) {
if (!(retu->id = calloc(strlen(id) + 1, 1)))
goto ERROR;
strcpy(retu->id, id);
} else {
if (!(retu->id = malloc(8)))
goto ERROR;
snprintf(retu->id, 8, "%u", random_int());
}
retu->level = level;
retu->start_time = current_time_monotonic();
fprintf(retu->log_file, "Successfully created and running logger id: %s; time: %s\n",
retu->id, strtime(retu->tstr, 16));
return retu;
ERROR:
fprintf(stderr, "Failed to create logger!\n");
pthread_mutex_destroy(retu->mutex);
fclose(retu->log_file);
free(retu->tstr);
free(retu->posstr);
free(retu->msg);
free(retu->id);
free(retu);
return NULL;
}
#endif /* LOGGING */
void logger_kill(logger* log)
{
#ifndef LOGGING /* Disabled */
return;
#endif
if (!log)
return;
pthread_mutex_lock(log->mutex);
free(log->id);
free(log->tstr);
free(log->posstr);
free(log->msg);
if (fclose(log->log_file) != 0 )
perror("Could not close log file");
pthread_mutex_unlock(log->mutex);
pthread_mutex_destroy(log->mutex);
free(log);
}
void logger_kill_global(void)
{
logger_kill(global);
}
void logger_set_global(logger* log)
{
#ifndef LOGGING /* Disabled */
return;
#endif
global = log;
}
logger* logger_get_global(void)
{
#ifndef LOGGING /* Disabled */
return NULL;
#endif
return global;
}
void logger_write (logger* log, LOG_LEVEL level, const char* file, int line, const char *format, ...)
{
#ifndef LOGGING /* Disabled */
return;
#endif
static const char* logger_format =
"%s " /* Logger id string */
"%-16s" /* Time string of format: %m:%d %H:%M:%S */
"%u " /* Thread id */
"%-5s " /* Logger lever string */
"%-20s " /* File:line string */
"- %s" /* Output message */
"\n"; /* Every new print new line */
logger* this_log = log ? log: global;
if (!this_log)
return;
/* Don't print levels lesser than set one */
if (this_log->level > level)
return;
pthread_mutex_lock(this_log->mutex);
/* Set position str */
snprintf(this_log->posstr, 300, "%s:%d", SFILE(file), line);
/* Set message */
va_list args;
va_start (args, format);
vsnprintf(this_log->msg, 4096, format, args);
va_end (args);
fprintf(this_log->log_file, logger_format, this_log->id, strtime(this_log->tstr, 16), pthread_self(),
LOG_LEVEL_STR[level], this_log->posstr, this_log->msg);
fflush(this_log->log_file);
pthread_mutex_unlock(this_log->mutex);
}

View File

@ -1,6 +1,4 @@
/* logger.h
*
* Wrapping logger functions in nice macros
*
* Copyright (C) 2013 Tox project All Rights Reserved.
*
@ -22,67 +20,74 @@
*/
#ifndef __TOXLOGGER
#define __TOXLOGGER
#ifndef TOXLOGGER_H
#define TOXLOGGER_H
#include <string.h>
#ifdef LOGGING
typedef enum _LoggerLevel {
INFO,
DEBUG,
WARNING,
ERROR
} LoggerLevel;
/*
* Set 'level' as the lowest printable level
*/
int logger_init(const char *file_name, LoggerLevel level);
const char *logger_stringify_level(LoggerLevel level);
unsigned logger_get_pid();
void logger_write (LoggerLevel level, const char *format, ...);
char *logger_timestr (char *dest, size_t max_size);
char *logger_posstr (char *dest, size_t max_size, const char *file, int line);
#if defined(_WIN32) || defined(__WIN32__) || defined (WIN32)
#define _SFILE (strrchr(__FILE__, '\\') ? strrchr(__FILE__, '\\') + 1 : __FILE__)
#else
#define _SFILE (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILE__)
/* In case these are undefined; define 'empty' */
#ifndef LOGGER_OUTPUT_FILE
# define LOGGER_OUTPUT_FILE ""
#endif
#define LFORMAT "\n%-15s %-7u %-5s %-20s - %s"
#define WRITE_FORMAT(__LEVEL__, __WHAT__) \
char __time__[15]; char posstr[200]; char the_str [4096]; \
snprintf(the_str, 4096, LFORMAT, logger_timestr(__time__, 15), logger_get_pid(), \
logger_stringify_level(__LEVEL__), logger_posstr(posstr, 200, _SFILE, __LINE__), __WHAT__)
#ifndef LOGGER_LEVEL
# define LOGGER_LEVEL LOG_ERROR
#endif
/* Use these macros */
#define LOGGER_INIT(name, level) logger_init(name, level);
#define LOGGER_INFO(format, ...) do { WRITE_FORMAT(INFO, format); logger_write( INFO, the_str, ##__VA_ARGS__ ); } while (0)
#define LOGGER_DEBUG(format, ...) do { WRITE_FORMAT(DEBUG, format); logger_write( DEBUG, the_str, ##__VA_ARGS__ ); } while (0)
#define LOGGER_WARNING(format, ...) do { WRITE_FORMAT(WARNING, format); logger_write( WARNING, the_str, ##__VA_ARGS__ ); } while (0)
#define LOGGER_ERROR(format, ...) do { WRITE_FORMAT(ERROR, format); logger_write( ERROR, the_str, ##__VA_ARGS__ ); } while (0)
typedef enum {
LOG_TRACE,
LOG_DEBUG,
LOG_INFO,
LOG_WARNING,
LOG_ERROR
} LOG_LEVEL;
/* To do some checks or similar only when logging use this */
#define LOGGER_SCOPE(__SCOPE_DO__) do { __SCOPE_DO__ } while(0)
typedef struct logger logger;
/**
* Set 'level' as the lowest printable level. If id == NULL, random number is used.
*/
logger* logger_new (const char *file_name, LOG_LEVEL level, const char* id);
void logger_kill (logger* log);
void logger_kill_global (void);
/**
* Global logger setter and getter.
*/
void logger_set_global (logger* log);
logger* logger_get_global (void);
/**
* Main write function. If logging disabled does nothing. If log == NULL uses global logger.
*/
void logger_write (logger* log, LOG_LEVEL level, const char* file, int line, const char* format, ...);
/* To do some checks or similar only when logging, use this */
#ifdef LOGGING
# define LOGGER_SCOPE(__SCOPE_DO__) do { __SCOPE_DO__ } while(0)
# define LOGGER_WRITE(log, level, format, ...) \
logger_write(log, level, __FILE__, __LINE__, format, ##__VA_ARGS__ )
#else
#define LOGGER_INIT(name, level) do {} while(0)
#define LOGGER_INFO(format, ...) do {} while(0)
#define LOGGER_DEBUG(format, ...) do {} while(0)
#define LOGGER_WARNING(format, ...) do {} while(0)
#define LOGGER_ERROR(format, ...) do {} while(0)
#define LOGGER_SCOPE(__SCOPE_DO__) do {} while(0)
# define LOGGER_SCOPE(__SCOPE_DO__) do {} while(0)
# define LOGGER_WRITE(log, level, format, ...) do {} while(0)
#endif /* LOGGING */
/* To log with an logger */
#define LOGGER_TRACE_(log, format, ...) LOGGER_WRITE(log, LOG_TRACE, format, ##__VA_ARGS__ )
#define LOGGER_DEBUG_(log, format, ...) LOGGER_WRITE(log, LOG_DEBUG, format, ##__VA_ARGS__ )
#define LOGGER_INFO_(log, format, ...) LOGGER_WRITE(log, LOG_INFO, format, ##__VA_ARGS__ )
#define LOGGER_WARNING_(log, format, ...) LOGGER_WRITE(log, LOG_WARNING, format, ##__VA_ARGS__ )
#define LOGGER_ERROR_(log, format, ...) LOGGER_WRITE(log, LOG_ERROR, format, ##__VA_ARGS__ )
/* To log with the global logger */
#define LOGGER_TRACE(format, ...) LOGGER_TRACE_(NULL, format, ##__VA_ARGS__)
#define LOGGER_DEBUG(format, ...) LOGGER_DEBUG_(NULL, format, ##__VA_ARGS__)
#define LOGGER_INFO(format, ...) LOGGER_INFO_(NULL, format, ##__VA_ARGS__)
#define LOGGER_WARNING(format, ...) LOGGER_WARNING_(NULL, format, ##__VA_ARGS__)
#define LOGGER_ERROR(format, ...) LOGGER_ERROR_(NULL, format, ##__VA_ARGS__)
#endif /* __TOXLOGGER */
#endif /* TOXLOGGER_H */

View File

@ -264,15 +264,15 @@ uint64_t current_time_monotonic(void)
#define loglogdata(__message__, __buffer__, __buflen__, __ip_port__, __res__) \
(__ip_port__) .ip; \
if (__res__ < 0) /* Windows doesn't necessarily know %zu */ \
LOGGER_INFO("[%2u] %s %3hu%c %s:%hu (%u: %s) | %04x%04x", \
LOGGER_TRACE("[%2u] %s %3hu%c %s:%hu (%u: %s) | %04x%04x", \
__buffer__[0], __message__, (__buflen__ < 999 ? (uint16_t)__buflen__ : 999), 'E', \
ip_ntoa(&((__ip_port__).ip)), ntohs((__ip_port__).port), errno, strerror(errno), data_0(__buflen__, __buffer__), data_1(__buflen__, __buffer__)); \
else if ((__res__ > 0) && ((size_t)__res__ <= __buflen__)) \
LOGGER_INFO("[%2u] %s %3zu%c %s:%hu (%u: %s) | %04x%04x", \
LOGGER_TRACE("[%2u] %s %3zu%c %s:%hu (%u: %s) | %04x%04x", \
__buffer__[0], __message__, (__res__ < 999 ? (size_t)__res__ : 999), ((size_t)__res__ < __buflen__ ? '<' : '='), \
ip_ntoa(&((__ip_port__).ip)), ntohs((__ip_port__).port), 0, "OK", data_0(__buflen__, __buffer__), data_1(__buflen__, __buffer__)); \
else /* empty or overwrite */ \
LOGGER_INFO("[%2u] %s %zu%c%zu %s:%hu (%u: %s) | %04x%04x", \
LOGGER_TRACE("[%2u] %s %zu%c%zu %s:%hu (%u: %s) | %04x%04x", \
__buffer__[0], __message__, (size_t)__res__, (!__res__ ? '!' : '>'), __buflen__, \
ip_ntoa(&((__ip_port__).ip)), ntohs((__ip_port__).port), 0, "OK", data_0(__buflen__, __buffer__), data_1(__buflen__, __buffer__));

View File

@ -1012,7 +1012,9 @@ uint32_t tox_do_interval(Tox *tox)
*/
Tox *tox_new(Tox_Options *options)
{
LOGGER_INIT(LOGGER_OUTPUT_FILE, LOGGER_LEVEL);
logger_set_global(logger_new(LOGGER_OUTPUT_FILE, LOGGER_LEVEL, "toxcore"));
Messenger_Options m_options = {0};
if (options == NULL) {
@ -1066,6 +1068,7 @@ void tox_kill(Tox *tox)
Messenger *m = tox;
kill_groupchats(m->group_chat_object);
kill_messenger(m);
logger_kill_global();
}
/* The main loop that needs to be run at least 20 times per second. */