From dcd58d8281e15905157bc10b6cfc0be478bf48b4 Mon Sep 17 00:00:00 2001 From: Bogomil Vasilev Date: Mon, 8 Aug 2016 22:31:29 +0300 Subject: [PATCH] Rewrite log_trace to be thread-safe and some cleanups --- confparser.c | 51 +++++++++++++++++---------------- confparser.h | 1 + log_trace.c | 78 +++++++++++++++++++++++++-------------------------- main.c | 5 ++-- rmps.c | 9 +++--- thread_pool.c | 2 +- tmp/rmpsd.err | 0 tmp/rmpsd.log | 55 ++++++++++++++++++++++++++++++++++++ 8 files changed, 127 insertions(+), 74 deletions(-) create mode 100644 tmp/rmpsd.err create mode 100644 tmp/rmpsd.log diff --git a/confparser.c b/confparser.c index 75b5c3d..0483c13 100644 --- a/confparser.c +++ b/confparser.c @@ -12,6 +12,7 @@ static int test_conf_perms(); static int test_conf_syntax(); struct conf_table conf = { + 0, /* isvalid initial state */ { "", /* db.type */ "", /* db.hostname */ @@ -22,7 +23,7 @@ struct conf_table conf = { "7000", /* rmps.bind_on_port */ "/var/log/rmps/rmpsd.log", "/var/log/rmps/rmpsd.err", - '1', /* rmps.loglevel */ + '2', /* rmps.loglevel */ "/run/rmps/rmpsd.pid", "/etc/rmps/cert.pem", "/etc/rmps/key.pem", @@ -82,8 +83,8 @@ static int fopen_and_mkdir(const char *dir) { if(*p == '/') { *p = 0; if (mkdir(tmp, S_IRWXU) == -1 && errno != EEXIST) { - fprintf( stderr, - "Permission denied to create directory: %s\n", + log_trace( ERROR, + "Permission denied to create directory: %s", tmp ); return 1; } @@ -91,7 +92,7 @@ static int fopen_and_mkdir(const char *dir) { } fd = fopen(dir, "a"); if (!fd) { - fprintf(stderr, "Permission denied to write into: %s\n", dir); + log_trace(ERROR, "Permission denied to write into: %s", dir); return 1; } fclose(fd); @@ -171,7 +172,6 @@ static int test_conf_perms() log_trace(WARNING, confresult); } } - return 0; /* conf is readable */ } @@ -198,8 +198,8 @@ static int test_conf_syntax() if ((tmp = strstr(buf, "="))) *tmp = '\0'; else { - fprintf( stderr, - "Bad entry in /etc/rmps/rmps.conf, line %d: %s\n", + log_trace( ERROR, + "Bad entry in /etc/rmps/rmps.conf, line %d: %s", j, buf ); ok = 0; failed = 1; @@ -210,8 +210,8 @@ static int test_conf_syntax() if (tmp[i] == '\n') tmp[i] = '\0'; if (tmp[strspn(tmp + 1, " \t\v\r\n") + 1] == '\0') { - fprintf( stderr, - "Specified entry without value, line %d: %s\n", + log_trace( ERROR, + "Specified entry without value, line %d: %s", j, buf ); failed = 1; continue; @@ -278,29 +278,28 @@ static int test_conf_syntax() failed = 1; } else if (!strcmp(buf, "rmps.certfile")) { if (access(tmp + 1, F_OK) == -1) { - fprintf( stderr, - "%s is missing\n", tmp + 1); + log_trace( ERROR, + "%s is missing", tmp + 1); failed = 1; } else if (access(tmp + 1, R_OK) == -1) { - fprintf( stderr, - "%s is not readable\n", + log_trace( ERROR, + "%s is not readable", tmp + 1 ); failed = 1; } else strncpy(conf.rmps.certfile, tmp + 1, sizeof(conf.rmps.certfile)); } - else if (!strcmp(buf, "rmps.keyfile")) { if (access(tmp + 1, F_OK) == -1) { - fprintf( stderr, - "%s is missing\n", conf.rmps.keyfile); + log_trace( ERROR, + "%s is missing", conf.rmps.keyfile); failed = 1; } else if (access(tmp + 1, R_OK) == -1) { - fprintf( stderr, - "%s is not readable\n", + log_trace( ERROR, + "%s is not readable", tmp + 1 ); failed = 1; @@ -310,12 +309,12 @@ static int test_conf_syntax() strncpy(conf.rmps.cipherlist, tmp + 1, sizeof(conf.rmps.cipherlist)); } else if (!strcmp(buf, "rmps.cafile")) { if (access(tmp + 1, F_OK) == -1) { - fprintf( stderr, - "%s is missing\n", tmp + 1); + log_trace( ERROR, + "%s is missing", tmp + 1); failed = 1; } else if (access(tmp + 1, R_OK) == -1) { - fprintf( stderr, + log_trace( ERROR, "%s is not readable\n", tmp + 1 ); @@ -323,12 +322,12 @@ static int test_conf_syntax() } else strncpy(conf.rmps.cafile, tmp + 1, sizeof(conf.rmps.cafile)); } else - fprintf( stderr, - "Unknown config entry on line %d: %s\n", + log_trace( ERROR, + "Unknown config entry on line %d: %s", j, buf ); if (!ok) { - fprintf( stderr, - "Invalid value for \"%s\", line %d: \"%s\"\n", + log_trace( ERROR, + "Invalid value for \"%s\", line %d: \"%s\"", buf, j, tmp + 1 ); ok = !ok; } @@ -337,6 +336,7 @@ static int test_conf_syntax() if (failed) return 1; + conf.isvalid = 1; return 0; } @@ -351,6 +351,5 @@ int confparse() result = test_conf_syntax(); if (result != 0) return 1; /* Bad conf syntax */ - return 0; /* seems legit */ } diff --git a/confparser.h b/confparser.h index b2a05ae..b2aa336 100644 --- a/confparser.h +++ b/confparser.h @@ -30,6 +30,7 @@ struct conf_nfs { }; struct conf_table { + int isvalid; struct conf_db db; struct conf_rmps rmps; struct conf_nfs nfs; diff --git a/log_trace.c b/log_trace.c index 63e2e66..44dcf61 100644 --- a/log_trace.c +++ b/log_trace.c @@ -1,64 +1,62 @@ #include #include #include +#include #include "log_trace.h" #include "confparser.h" +static FILE *fderr = NULL; +static FILE *fdout = NULL; +static pthread_once_t once = PTHREAD_ONCE_INIT; +static void open_logs(void) + +{ + if (conf.rmps.errlog) + fderr = fopen(conf.rmps.errlog, "a"); + if (conf.rmps.logfile) + fdout = fopen(conf.rmps.logfile, "a"); +} + void log_trace(LOG_LEVEL lvl, char *fmt, ... ) { LOG_LEVEL cur_lvl = conf.rmps.loglevel - '0'; + + if (conf.isvalid) + pthread_once(&once, open_logs); if (lvl <= cur_lvl) { va_list list; - int fallback = 0; FILE *fd; + static const char *prefixes[] = { + "ERROR", "WARNING", "INFO", "VERBOSE" + }; time_t t = time(NULL); struct tm tm = *localtime(&t); - if (lvl == ERROR || lvl == WARNING) { - fd = fopen(conf.rmps.errlog, "a"); - if (!fd) { - fprintf( stderr, - "Failed to append errlog: %s. Redirecting to stderr:\n", - conf.rmps.errlog ); - fd = stderr; - fallback = 1; - } - fprintf( fd, - "[%d-%02d-%02d %02d:%02d:%02d] %s: ", - tm.tm_year + 1900, - tm.tm_mon + 1, - tm.tm_mday, - tm.tm_hour, - tm.tm_min, - tm.tm_sec, - lvl == ERROR ? "ERROR" : "WARNING" ); - } else { - fd = fopen(conf.rmps.logfile, "a"); - if (!fd) { - fprintf( stderr, - "Failed to append logfile: %s. Redirecting to stderr:\n", - conf.rmps.logfile ); - fd = stderr; - fallback = 1; - } - fprintf( fd, - "[%d-%02d-%02d %02d:%02d:%02d] %s: ", - tm.tm_year + 1900, - tm.tm_mon + 1, - tm.tm_mday, - tm.tm_hour, - tm.tm_min, - tm.tm_sec, - lvl == INFO ? "INFO" : "VERBOSE" ); + if (lvl == ERROR || lvl == WARNING) + fd = fderr; + else + fd = fdout; + if (!fd) { + fprintf( stderr, + "Failed to append errlog: %s. Redirecting to stderr:\n", + conf.rmps.errlog ); + fd = stderr; } + fprintf( fd, + "[%d-%02d-%02d %02d:%02d:%02d] %s: ", + tm.tm_year + 1900, + tm.tm_mon + 1, + tm.tm_mday, + tm.tm_hour, + tm.tm_min, + tm.tm_sec, + prefixes[lvl-1] ); va_start(list, fmt); vfprintf(fd, fmt, list); fprintf(fd, "\n"); + fflush(fd); va_end(list); - if (!fallback) - fclose(fd); } else return; - fflush(stdout); } diff --git a/main.c b/main.c index 4d12254..3f2403d 100644 --- a/main.c +++ b/main.c @@ -10,7 +10,7 @@ static void usage(char *argv) { - fprintf( stderr, + log_trace( ERROR, "Usage:\n%s start|stop|restart [--daemonize=yes|no]\n", argv ); } @@ -45,9 +45,10 @@ int main(int argc, char *argv[]) } } if (confparse() != 0) { - fprintf(stderr, "Failed to parse the conf!"); + log_trace(ERROR, "Failed to parse the conf!"); exit(EXIT_FAILURE); } + log_trace(VERBOSE, "Conf parser finished successfully"); //confexport(); if (task == 2 || task == 3) { diff --git a/rmps.c b/rmps.c index f21b4b0..f82588d 100644 --- a/rmps.c +++ b/rmps.c @@ -99,7 +99,6 @@ static void daemonize(const char *rundir) } /* Fork*/ pid = fork(); - /*printf("fork() = %d\n", pid);*/ if (pid < 0) { /* Could not fork */ log_trace(ERROR, "Failed to fork the parent process. Exiting!"); @@ -118,10 +117,10 @@ static void daemonize(const char *rundir) log_trace(ERROR, "Failed to create a process group. Exiting!"); exit(EXIT_FAILURE); } - /* Close all file descriptors because we fork */ - for (i = getdtablesize(); i >= 0; --i) - close(i); - + /* Close all file descriptors because we fork */ + close(0); /* stdin */ + close(1); /* stdout */ + close(2); /* stderr */ /* Route I/O connections */ /* Open STDIN */ i = open("/dev/null", O_RDWR); diff --git a/thread_pool.c b/thread_pool.c index e8ef622..498fae4 100644 --- a/thread_pool.c +++ b/thread_pool.c @@ -52,7 +52,7 @@ static void* servlet(void *args) /* Serve the connection -- threadable */ if (ret <= 0) { char ret_str[1024]; ERR_error_string_n(SSL_get_error(agent->ssl, ret), ret_str, sizeof(ret_str)); - log_trace(INFO, "SSL_accept() failed. Reason below:\n%s", ret_str); + log_trace(WARNING, "SSL_accept() failed. Reason below:\n%s", ret_str); } else { show_certs(agent->ssl); do { diff --git a/tmp/rmpsd.err b/tmp/rmpsd.err new file mode 100644 index 0000000..e69de29 diff --git a/tmp/rmpsd.log b/tmp/rmpsd.log new file mode 100644 index 0000000..1b710e6 --- /dev/null +++ b/tmp/rmpsd.log @@ -0,0 +1,55 @@ +[2016-08-08 21:05:10] INFO: Starting up RMPS... +[2016-08-08 21:05:13] INFO: Received SIGTERM signal. +[2016-08-08 21:05:13] INFO: RMPS is shutting down... +[2016-08-08 21:05:13] INFO: RMPS has been stopped properly. +[2016-08-08 21:05:40] INFO: Starting up RMPS... +[2016-08-08 21:05:40] INFO: Child process created: 32737 +[2016-08-08 21:05:50] INFO: Received SIGTERM signal. +[2016-08-08 21:05:50] INFO: RMPS is shutting down... +[2016-08-08 21:05:50] INFO: RMPS has been stopped properly. +[2016-08-08 21:05:54] INFO: Starting up RMPS... +[2016-08-08 21:05:54] INFO: Child process created: 32762 +[2016-08-08 21:05:57] INFO: Received SIGTERM signal. +[2016-08-08 21:05:57] INFO: RMPS is shutting down... +[2016-08-08 21:05:57] INFO: RMPS has been stopped properly. +[2016-08-08 21:20:18] INFO: Starting up RMPS... +[2016-08-08 21:20:19] INFO: Received SIGTERM signal. +[2016-08-08 21:20:19] INFO: RMPS is shutting down... +[2016-08-08 21:20:19] INFO: RMPS has been stopped properly. +[2016-08-08 21:20:25] INFO: Starting up RMPS... +[2016-08-08 21:20:25] INFO: Child process created: 2371 +[2016-08-08 21:20:28] INFO: Received SIGTERM signal. +[2016-08-08 21:20:28] INFO: RMPS is shutting down... +[2016-08-08 21:20:28] INFO: RMPS has been stopped properly. +[2016-08-08 22:01:35] INFO: Starting up RMPS... +[2016-08-08 22:01:38] INFO: Received SIGTERM signal. +[2016-08-08 22:01:38] INFO: RMPS is shutting down... +[2016-08-08 22:01:38] INFO: RMPS has been stopped properly. +[2016-08-08 22:01:43] INFO: Starting up RMPS... +[2016-08-08 22:01:44] INFO: Received SIGTERM signal. +[2016-08-08 22:01:44] INFO: RMPS is shutting down... +[2016-08-08 22:01:44] INFO: RMPS has been stopped properly. +[2016-08-08 22:02:19] INFO: Starting up RMPS... +[2016-08-08 22:02:19] INFO: Child process created: 6212 +[2016-08-08 22:02:19] INFO: stdin.fd=0 stdout.fd=1 stderr.fd=2 + +[2016-08-08 22:02:22] INFO: Received SIGTERM signal. +[2016-08-08 22:02:22] INFO: RMPS is shutting down... +[2016-08-08 22:02:22] INFO: RMPS has been stopped properly. +[2016-08-08 22:03:21] INFO: Starting up RMPS... +[2016-08-08 22:03:26] INFO: Received SIGTERM signal. +[2016-08-08 22:03:26] INFO: RMPS is shutting down... +[2016-08-08 22:03:26] INFO: RMPS has been stopped properly. +[2016-08-08 22:03:32] INFO: Starting up RMPS... +[2016-08-08 22:03:32] INFO: Child process created: 6356 +[2016-08-08 22:03:32] INFO: stdin.fd=0 stdout.fd=1 stderr.fd=2 + +[2016-08-08 22:03:32] INFO: stdin.fd=0 stdout.fd=1 stderr.fd=2 + +[2016-08-08 22:03:36] INFO: Received SIGTERM signal. +[2016-08-08 22:03:36] INFO: RMPS is shutting down... +[2016-08-08 22:03:36] INFO: RMPS has been stopped properly. +[2016-08-08 22:29:17] INFO: Starting up RMPS... +[2016-08-08 22:29:18] INFO: Received SIGTERM signal. +[2016-08-08 22:29:18] INFO: RMPS is shutting down... +[2016-08-08 22:29:18] INFO: RMPS has been stopped properly.