From c1ff9a326120520ea907ab81577d611e179fb87c Mon Sep 17 00:00:00 2001 From: paulo Date: Mon, 30 Nov 2009 17:19:02 +0000 Subject: Make logging (lib.c) and privileges (privs.c) pthread safe lib.c: use a mutex to protect all public methods. Replaced code in command.c etc that modified zlog_default directly with interlocked getters and setters. Requires that vty_log in vty.c handles its own pthread safety TBA. privs.c: use a mutex to protect all public methods. Counts RAISE and LOWER so that privilege stays RAISED until all pthreads have lowered. Improved messages in test-privs.c --- lib/log.c | 527 ++++++++++++++++++++++++++++++++++++++++++++++++++------------ 1 file changed, 431 insertions(+), 96 deletions(-) (limited to 'lib/log.c') diff --git a/lib/log.c b/lib/log.c index 0c2f655b..f2273a4b 100644 --- a/lib/log.c +++ b/lib/log.c @@ -34,6 +34,18 @@ #ifdef HAVE_UCONTEXT_H #include #endif +#include +#include + +/* logging needs to be pthread safe */ +static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER; +#ifdef NDEBUG +#define LOCK pthread_mutex_lock(&mutex); +#define UNLOCK pthread_mutex_unlock(&mutex); +#else +#define LOCK if(pthread_mutex_lock(&mutex)!= 0){assert(0);}; +#define UNLOCK if(pthread_mutex_unlock(&mutex)!= 0){assert(0);}; +#endif static int logfile_fd = -1; /* Used in signal handler. */ @@ -81,6 +93,10 @@ quagga_timestamp(int timestamp_precision, char *buf, size_t buflen) } cache; struct timeval clock; + size_t result = 0; + + LOCK + /* would it be sufficient to use global 'recent_time' here? I fear not... */ gettimeofday(&clock, NULL); @@ -122,14 +138,20 @@ quagga_timestamp(int timestamp_precision, char *buf, size_t buflen) } while (--prec > 0); *p = '.'; - return cache.len+1+timestamp_precision; + result = cache.len+1+timestamp_precision; } - buf[cache.len] = '\0'; - return cache.len; + else + { + buf[cache.len] = '\0'; + result = cache.len; + } + } else { + if (buflen > 0) + buf[0] = '\0'; } - if (buflen > 0) - buf[0] = '\0'; - return 0; + + UNLOCK + return result; } /* Utility routine for current time printing. */ @@ -152,6 +174,8 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args) struct timestamp_control tsctl; tsctl.already_rendered = 0; + LOCK + /* If zlog is not specified, use default one. */ if (zl == NULL) zl = zlog_default; @@ -165,55 +189,65 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args) vfprintf (stderr, format, args); fprintf (stderr, "\n"); fflush (stderr); - - /* In this case we return at here. */ - return; } - tsctl.precision = zl->timestamp_precision; - - /* Syslog output */ - if (priority <= zl->maxlvl[ZLOG_DEST_SYSLOG]) + else { - va_list ac; - va_copy(ac, args); - vsyslog (priority|zlog_default->facility, format, ac); - va_end(ac); - } + tsctl.precision = zl->timestamp_precision; - /* File output. */ - if ((priority <= zl->maxlvl[ZLOG_DEST_FILE]) && zl->fp) - { - va_list ac; - time_print (zl->fp, &tsctl); - if (zl->record_priority) - fprintf (zl->fp, "%s: ", zlog_priority[priority]); - fprintf (zl->fp, "%s: ", zlog_proto_names[zl->protocol]); - va_copy(ac, args); - vfprintf (zl->fp, format, ac); - va_end(ac); - fprintf (zl->fp, "\n"); - fflush (zl->fp); - } + /* Syslog output */ + if (priority <= zl->maxlvl[ZLOG_DEST_SYSLOG]) + { + va_list ac; + va_copy(ac, args); + vsyslog (priority|zlog_default->facility, format, ac); + va_end(ac); + } - /* stdout output. */ - if (priority <= zl->maxlvl[ZLOG_DEST_STDOUT]) - { - va_list ac; - time_print (stdout, &tsctl); - if (zl->record_priority) - fprintf (stdout, "%s: ", zlog_priority[priority]); - fprintf (stdout, "%s: ", zlog_proto_names[zl->protocol]); - va_copy(ac, args); - vfprintf (stdout, format, ac); - va_end(ac); - fprintf (stdout, "\n"); - fflush (stdout); - } + /* File output. */ + if ((priority <= zl->maxlvl[ZLOG_DEST_FILE]) && zl->fp) + { + va_list ac; + time_print (zl->fp, &tsctl); + if (zl->record_priority) + fprintf (zl->fp, "%s: ", zlog_priority[priority]); + fprintf (zl->fp, "%s: ", zlog_proto_names[zl->protocol]); + va_copy(ac, args); + vfprintf (zl->fp, format, ac); + va_end(ac); + fprintf (zl->fp, "\n"); + fflush (zl->fp); + } - /* Terminal monitor. */ - if (priority <= zl->maxlvl[ZLOG_DEST_MONITOR]) - vty_log ((zl->record_priority ? zlog_priority[priority] : NULL), - zlog_proto_names[zl->protocol], format, &tsctl, args); + /* stdout output. */ + if (priority <= zl->maxlvl[ZLOG_DEST_STDOUT]) + { + va_list ac; + time_print (stdout, &tsctl); + if (zl->record_priority) + fprintf (stdout, "%s: ", zlog_priority[priority]); + fprintf (stdout, "%s: ", zlog_proto_names[zl->protocol]); + va_copy(ac, args); + vfprintf (stdout, format, ac); + va_end(ac); + fprintf (stdout, "\n"); + fflush (stdout); + } + + /* Terminal monitor. */ + if (priority <= zl->maxlvl[ZLOG_DEST_MONITOR]) + { + /* must be unlocked as vty handles it's own pthread stuff + * extract what we need from the zlog first + */ + const char *priority_name = (zl->record_priority ? zlog_priority[priority] : NULL); + const char *proto_name = zlog_proto_names[zl->protocol]; + + UNLOCK + vty_log (priority_name, proto_name, format, &tsctl, args); + return; + } + } + UNLOCK } static char * @@ -608,12 +642,16 @@ _zlog_assert_failed (const char *assertion, const char *file, unsigned int line, const char *function) { /* Force fallback file logging? */ + LOCK if (zlog_default && !zlog_default->fp && ((logfile_fd = open_crashlog()) >= 0) && ((zlog_default->fp = fdopen(logfile_fd, "w")) != NULL)) zlog_default->maxlvl[ZLOG_DEST_FILE] = LOG_ERR; + UNLOCK + zlog(NULL, LOG_CRIT, "Assertion `%s' failed in file %s, line %u, function %s", assertion,file,line,(function ? function : "?")); + zlog_backtrace(LOG_CRIT); abort(); } @@ -648,22 +686,33 @@ openzlog (const char *progname, zlog_proto_t protocol, void closezlog (struct zlog *zl) { + LOCK + closelog(); if (zl->fp != NULL) fclose (zl->fp); XFREE (MTYPE_ZLOG, zl); + + UNLOCK } /* Called from command.c. */ void zlog_set_level (struct zlog *zl, zlog_dest_t dest, int log_level) { + LOCK + if (zl == NULL) zl = zlog_default; - zl->maxlvl[dest] = log_level; + if (zl != NULL) + { + zl->maxlvl[dest] = log_level; + } + + UNLOCK } int @@ -671,6 +720,9 @@ zlog_set_file (struct zlog *zl, const char *filename, int log_level) { FILE *fp; mode_t oldumask; + int result = 0; + + LOCK /* There is opend file. */ zlog_reset_file (zl); @@ -679,39 +731,51 @@ zlog_set_file (struct zlog *zl, const char *filename, int log_level) if (zl == NULL) zl = zlog_default; - /* Open file. */ - oldumask = umask (0777 & ~LOGFILE_MASK); - fp = fopen (filename, "a"); - umask(oldumask); - if (fp == NULL) - return 0; - - /* Set flags. */ - zl->filename = strdup (filename); - zl->maxlvl[ZLOG_DEST_FILE] = log_level; - zl->fp = fp; - logfile_fd = fileno(fp); + if (zl != NULL) + { + /* Open file. */ + oldumask = umask (0777 & ~LOGFILE_MASK); + fp = fopen (filename, "a"); + umask(oldumask); + if (fp == NULL) + result = 0; + else + { + /* Set flags. */ + zl->filename = strdup (filename); + zl->maxlvl[ZLOG_DEST_FILE] = log_level; + zl->fp = fp; + logfile_fd = fileno(fp); + } + } - return 1; + UNLOCK + return result; } /* Reset opend file. */ int zlog_reset_file (struct zlog *zl) { + LOCK + if (zl == NULL) zl = zlog_default; - if (zl->fp) - fclose (zl->fp); - zl->fp = NULL; - logfile_fd = -1; - zl->maxlvl[ZLOG_DEST_FILE] = ZLOG_DISABLED; - - if (zl->filename) - free (zl->filename); - zl->filename = NULL; + if (zl != NULL) + { + if (zl->fp) + fclose (zl->fp); + zl->fp = NULL; + logfile_fd = -1; + zl->maxlvl[ZLOG_DEST_FILE] = ZLOG_DISABLED; + + if (zl->filename) + free (zl->filename); + zl->filename = NULL; + } + UNLOCK return 1; } @@ -721,38 +785,309 @@ zlog_rotate (struct zlog *zl) { int level; + LOCK + if (zl == NULL) zl = zlog_default; - if (zl->fp) - fclose (zl->fp); - zl->fp = NULL; - logfile_fd = -1; - level = zl->maxlvl[ZLOG_DEST_FILE]; - zl->maxlvl[ZLOG_DEST_FILE] = ZLOG_DISABLED; + if (zl != NULL) + { + if (zl->fp) + fclose (zl->fp); + zl->fp = NULL; + logfile_fd = -1; + level = zl->maxlvl[ZLOG_DEST_FILE]; + zl->maxlvl[ZLOG_DEST_FILE] = ZLOG_DISABLED; + + if (zl->filename) + { + mode_t oldumask; + int save_errno; + + oldumask = umask (0777 & ~LOGFILE_MASK); + zl->fp = fopen (zl->filename, "a"); + save_errno = errno; + umask(oldumask); + if (zl->fp == NULL) + { + /* can't call logging while locked */ + char *fname = strdup(zl->filename); + UNLOCK + zlog_err("Log rotate failed: cannot open file %s for append: %s", + fname, safe_strerror(save_errno)); + free(fname); + return -1; + } + else + { + logfile_fd = fileno(zl->fp); + zl->maxlvl[ZLOG_DEST_FILE] = level; + } + } + } + UNLOCK + return 1; +} + +int +zlog_get_default_lvl (struct zlog *zl) +{ + int result = LOG_DEBUG; + + LOCK + + if (zl == NULL) + zl = zlog_default; - if (zl->filename) + if (zl != NULL) { - mode_t oldumask; - int save_errno; + result = zl->default_lvl; + } - oldumask = umask (0777 & ~LOGFILE_MASK); - zl->fp = fopen (zl->filename, "a"); - save_errno = errno; - umask(oldumask); - if (zl->fp == NULL) - { - zlog_err("Log rotate failed: cannot open file %s for append: %s", - zl->filename, safe_strerror(save_errno)); - return -1; - } - logfile_fd = fileno(zl->fp); - zl->maxlvl[ZLOG_DEST_FILE] = level; + UNLOCK + return result; +} + +void +zlog_set_default_lvl (struct zlog *zl, int level) +{ + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + zl->default_lvl = level; } - return 1; + UNLOCK } - + +/* Set logging level and default for all destinations */ +void +zlog_set_default_lvl_dest (struct zlog *zl, int level) +{ + int i; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + zl->default_lvl = level; + + for (i = 0; i < ZLOG_NUM_DESTS; i++) + if (zl->maxlvl[i] != ZLOG_DISABLED) + zl->maxlvl[i] = level; + } + + UNLOCK +} + +int +zlog_get_maxlvl (struct zlog *zl, zlog_dest_t dest) +{ + int result = ZLOG_DISABLED; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = zl->maxlvl[dest]; + } + + UNLOCK + return result; +} + +int +zlog_get_facility (struct zlog *zl) +{ + int result = LOG_DAEMON; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = zl->facility; + } + + UNLOCK + return result; +} + +void +zlog_set_facility (struct zlog *zl, int facility) +{ + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + zl->facility = facility; + } + + UNLOCK +} + +int +zlog_get_record_priority (struct zlog *zl) +{ + int result = 0; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = zl->record_priority; + } + + UNLOCK + return result; +} + +void +zlog_set_record_priority (struct zlog *zl, int record_priority) +{ + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + zl->record_priority = record_priority; + } + UNLOCK +} + +int +zlog_get_timestamp_precision (struct zlog *zl) +{ + int result = 0; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = zl->timestamp_precision; + } + UNLOCK + return result; +} + +void +zlog_set_timestamp_precision (struct zlog *zl, int timestamp_precision) +{ + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + zl->timestamp_precision = timestamp_precision; + } + + UNLOCK +} + +/* returns name of ZLOG_NONE if no zlog given and no default set */ +const char * +zlog_get_proto_name (struct zlog *zl) +{ + zlog_proto_t protocol = ZLOG_NONE; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + protocol = zl->protocol; + } + + UNLOCK + return zlog_proto_names[protocol]; +} + +/* caller must free result */ +char * +zlog_get_filename (struct zlog *zl) +{ + char * result = NULL; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL && zl->filename != NULL) + { + result = strdup(zl->filename); + } + + UNLOCK + return result; +} + +const char * +zlog_get_ident (struct zlog *zl) +{ + const char * result = NULL; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = zl->ident; + } + + UNLOCK + return result; +} + +/* logging to a file? */ +int +zlog_is_file (struct zlog *zl) +{ + int result = 0; + + LOCK + + if (zl == NULL) + zl = zlog_default; + + if (zl != NULL) + { + result = (zl->fp != NULL); + } + + UNLOCK + return result; +} + /* Message lookup function. */ const char * lookup (const struct message *mes, int key) -- cgit v1.2.3 From 1e2ad204c4c72cb3ffa73864154c96047da8cad4 Mon Sep 17 00:00:00 2001 From: paulo Date: Tue, 1 Dec 2009 16:17:10 +0000 Subject: Fix nested LOCK bug --- lib/log.c | 38 ++++++++++++++++++++++++++++++-------- 1 file changed, 30 insertions(+), 8 deletions(-) (limited to 'lib/log.c') diff --git a/lib/log.c b/lib/log.c index f2273a4b..ab8bd47e 100644 --- a/lib/log.c +++ b/lib/log.c @@ -39,7 +39,11 @@ /* logging needs to be pthread safe */ static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER; -#ifdef NDEBUG +#if 0 +static int lock_count = 0; +#define LOCK if(lock_count++ != 0){printf("Lock count: %d\n", lock_count);assert(0);} +#define UNLOCK if(--lock_count != 0){printf("Unlock count: %d\n", lock_count);assert(0);} +#elif defined(NDEBUG) #define LOCK pthread_mutex_lock(&mutex); #define UNLOCK pthread_mutex_unlock(&mutex); #else @@ -47,6 +51,10 @@ static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER; #define UNLOCK if(pthread_mutex_unlock(&mutex)!= 0){assert(0);}; #endif +/* prototypes */ +static int do_reset_file (struct zlog *zl); +static size_t do_timestamp(int timestamp_precision, char *buf, size_t buflen); + static int logfile_fd = -1; /* Used in signal handler. */ struct zlog *zlog_default = NULL; @@ -85,6 +93,16 @@ const char *zlog_priority[] = size_t quagga_timestamp(int timestamp_precision, char *buf, size_t buflen) +{ + size_t result; + LOCK + result = do_timestamp(timestamp_precision, buf, buflen); + UNLOCK + return result; +} + +static size_t +do_timestamp(int timestamp_precision, char *buf, size_t buflen) { static struct { time_t last; @@ -95,8 +113,6 @@ quagga_timestamp(int timestamp_precision, char *buf, size_t buflen) size_t result = 0; - LOCK - /* would it be sufficient to use global 'recent_time' here? I fear not... */ gettimeofday(&clock, NULL); @@ -150,7 +166,6 @@ quagga_timestamp(int timestamp_precision, char *buf, size_t buflen) buf[0] = '\0'; } - UNLOCK return result; } @@ -160,7 +175,7 @@ time_print(FILE *fp, struct timestamp_control *ctl) { if (!ctl->already_rendered) { - ctl->len = quagga_timestamp(ctl->precision, ctl->buf, sizeof(ctl->buf)); + ctl->len = do_timestamp(ctl->precision, ctl->buf, sizeof(ctl->buf)); ctl->already_rendered = 1; } fprintf(fp, "%s ", ctl->buf); @@ -720,12 +735,12 @@ zlog_set_file (struct zlog *zl, const char *filename, int log_level) { FILE *fp; mode_t oldumask; - int result = 0; + int result = 1; LOCK /* There is opend file. */ - zlog_reset_file (zl); + do_reset_file (zl); /* Set default zl. */ if (zl == NULL) @@ -757,8 +772,16 @@ zlog_set_file (struct zlog *zl, const char *filename, int log_level) int zlog_reset_file (struct zlog *zl) { + int result; LOCK + result = do_reset_file(zl); + UNLOCK + return result; +} +static int +do_reset_file (struct zlog *zl) + { if (zl == NULL) zl = zlog_default; @@ -775,7 +798,6 @@ zlog_reset_file (struct zlog *zl) zl->filename = NULL; } - UNLOCK return 1; } -- cgit v1.2.3