logging cleanups

* Moved all logging-related stuff into log.c
(and not myfprintf.c)

* ISO C90-compliant strftime usage:
%e and %R replaced with %d and %H:%M respectively

* Got rid of variadic macros since some old-school compilers
don't like them

* compiling with -DNDEBUG disables the DEBUG() macro

git-svn-id: https://svn.musicpd.org/mpd/trunk@4512 09075e82-0dd4-0310-85a5-a0d7c8717e4f

src/decode.c

@@ -208,7 +208,7 @@ static int decodeSeek(PlayerControl * pc, DecoderControl * dc,
 
 #define processDecodeInput() \
         if(pc->cycleLogFiles) { \
-                myfprintfCloseAndOpenLogFile(); \
+                cycle_log_files(); \
                 pc->cycleLogFiles = 0; \
         } \
 	if(pc->lockQueue) { \
@@ -415,7 +415,7 @@ static int decoderInit(PlayerControl * pc, OutputBuffer * cb,
 
 		while (1) {
 			if (dc->cycleLogFiles) {
-				myfprintfCloseAndOpenLogFile();
+				cycle_log_files();
 				dc->cycleLogFiles = 0;
 			} else if (dc->start || dc->seek)
 				decodeStart(pc, cb, dc);

src/log.c

@@ -22,54 +22,73 @@
 #include "myfprintf.h"
 #include "utils.h"
 
+#include <assert.h>
 #include <stdlib.h>
 #include <string.h>
 #include <stdarg.h>
+#include <time.h>
 
-int logLevel = LOG_LEVEL_LOW;
+static unsigned int logLevel = LOG_LEVEL_LOW;
-short warningFlushed = 0;
+static int warningFlushed = 0;
-
+static int stdout_mode = 1;
 static char *warningBuffer = NULL;
+static int out_fd = -1;
+static int err_fd = -1;
+static const char *out_filename = NULL;
+static const char *err_filename = NULL;
 
-void initLog(void)
+/* redirect stdin to /dev/null to work around a libao bug */
+static void redirect_stdin(void)
 {
-	ConfigParam *param = getConfigParam(CONF_LOG_LEVEL);
+	int fd;
+	if ((fd = open("/dev/null", O_RDONLY)) < 0)
+		FATAL("failed to open /dev/null %s\n", strerror(errno));
+	if (dup2(fd, STDIN_FILENO) < 0)
+		FATAL("dup2 stdin: %s\n", strerror(errno));
+}
 
-	if (!param)
+static void redirect_logs(void)
-		return;
+{
+	assert(out_fd > 0);
+	assert(err_fd > 0);
+	if (dup2(out_fd, STDOUT_FILENO) < 0)
+		FATAL("problems dup2 stdout : %s\n", strerror(errno));
+	if (dup2(err_fd, STDERR_FILENO) < 0)
+		FATAL("problems dup2 stderr : %s\n", strerror(errno));
+}
 
-	if (0 == strcmp(param->value, "default")) {
+static const char *log_date(void)
-		if (logLevel < LOG_LEVEL_LOW)
+{
-			logLevel = LOG_LEVEL_LOW;
+	static char buf[16] = { '\0' };
-	} else if (0 == strcmp(param->value, "secure")) {
+	time_t t = time(NULL);
-		if (logLevel < LOG_LEVEL_SECURE)
+	strftime(buf, 16, "%b %d %H:%M : ", localtime(&t));
-			logLevel = LOG_LEVEL_SECURE;
+	return buf;
-	} else if (0 == strcmp(param->value, "verbose")) {
-		if (logLevel < LOG_LEVEL_DEBUG)
-			logLevel = LOG_LEVEL_DEBUG;
-	} else {
-		ERROR("unknown log level \"%s\" at line %i\n",
-		      param->value, param->line);
-		exit(EXIT_FAILURE);
-	}
 }
 
 #define BUFFER_LENGTH	4096
-
+static void buffer_warning(const char *fmt, va_list args)
-void bufferWarning(char *format, ...)
 {
-	va_list arglist;
+	char buffer[BUFFER_LENGTH + 1];
-	char temp[BUFFER_LENGTH + 1];
+	char *tmp = buffer;
+	size_t len = BUFFER_LENGTH;
 
-	memset(temp, 0, BUFFER_LENGTH + 1);
+	if (!stdout_mode) {
+		memcpy(buffer, log_date(), 15);
+		tmp += 15;
+		len -= 15;
+	}
 
-	va_start(arglist, format);
+	vsnprintf(tmp, len, fmt, args);
+	warningBuffer = appendToString(warningBuffer, buffer);
 
-	vsnprintf(temp, BUFFER_LENGTH, format, arglist);
+	va_end(args);
+}
 
-	warningBuffer = appendToString(warningBuffer, temp);
+static void do_log(const int fd, const char *fmt, va_list args)
-
+{
-	va_end(arglist);
+	if (!stdout_mode)
+		xwrite(fd, log_date(), 15);
+	vfdprintf(fd, fmt, args);
 }
 
 void flushWarningLog(void)
@@ -84,12 +103,155 @@ void flushWarningLog(void)
 	s = strtok(warningBuffer, "\n");
 	while (s != NULL) {
 		fdprintf(STDERR_FILENO, "%s\n", s);
-
 		s = strtok(NULL, "\n");
 	}
 
 	free(warningBuffer);
 	warningBuffer = NULL;
-
 	warningFlushed = 1;
 }
+
+void initLog(const int verbose)
+{
+	ConfigParam *param;
+
+	if (verbose) {
+		logLevel = LOG_LEVEL_DEBUG;
+		return;
+	}
+	if (!(param = getConfigParam(CONF_LOG_LEVEL)))
+		return;
+	if (0 == strcmp(param->value, "default")) {
+		logLevel = LOG_LEVEL_LOW;
+	} else if (0 == strcmp(param->value, "secure")) {
+		logLevel = LOG_LEVEL_SECURE;
+	} else if (0 == strcmp(param->value, "verbose")) {
+		logLevel = LOG_LEVEL_DEBUG;
+	} else {
+		FATAL("unknown log level \"%s\" at line %i\n",
+		      param->value, param->line);
+	}
+}
+
+void open_log_files(const int use_stdout)
+{
+	mode_t prev;
+	ConfigParam *param;
+
+	if (use_stdout) {
+		flushWarningLog();
+		return;
+	}
+
+	prev = umask(0066);
+	param = parseConfigFilePath(CONF_LOG_FILE, 1);
+	out_filename = param->value;
+	out_fd = xopen(out_filename, O_CREAT | O_WRONLY | O_APPEND, 0666);
+	if (out_fd < 0)
+		FATAL("problem opening log file \"%s\" (config line %i) for "
+		      "writing\n", param->value, param->line);
+
+	param = parseConfigFilePath(CONF_ERROR_FILE, 1);
+	err_filename = param->value;
+	err_fd = xopen(err_filename, O_CREAT | O_WRONLY | O_APPEND, 0666);
+	if (err_fd < 0)
+		FATAL("problem opening error file \"%s\" (config line %i) for "
+		      "writing\n", param->value, param->line);
+
+	umask(prev);
+}
+
+void setup_log_output(const int use_stdout)
+{
+	fflush(NULL);
+	if (!use_stdout) {
+		redirect_logs();
+		stdout_mode = 0;
+	}
+	redirect_stdin();
+}
+
+#define log_func(func,level,fd) \
+mpd_printf void func(const char *fmt, ...) \
+{ \
+	if (logLevel >= level) { \
+		va_list args; \
+		va_start(args, fmt); \
+		do_log(fd, fmt, args); \
+		va_end(args); \
+	} \
+}
+
+log_func(ERROR, 0, STDERR_FILENO)
+log_func(LOG, 0, STDOUT_FILENO)
+log_func(SECURE, LOG_LEVEL_SECURE, STDOUT_FILENO)
+
+#ifndef NDEBUG
+log_func(DEBUG, LOG_LEVEL_DEBUG, STDOUT_FILENO)
+#endif /* NDEBUG */
+
+#undef log_func
+
+void WARNING(const char *fmt, ...)
+{
+	va_list args;
+	va_start(args, fmt);
+	if (warningFlushed) {
+		do_log(STDERR_FILENO, fmt, args);
+	} else
+		buffer_warning(fmt, args);
+	va_end(args);
+}
+
+mpd_printf mpd_noreturn void FATAL(const char *fmt, ...)
+{
+	va_list args;
+	va_start(args, fmt);
+	do_log(STDERR_FILENO, fmt, args);
+	va_end(args);
+	exit(EXIT_FAILURE);
+}
+
+int cycle_log_files(void)
+{
+	mode_t prev;
+
+	if (stdout_mode)
+		return 0;
+	assert(out_filename);
+	assert(err_filename);
+
+	DEBUG("Cycling log files...\n");
+	close_log_files();
+
+	prev = umask(0066);
+
+	out_fd = xopen(out_filename, O_CREAT | O_WRONLY | O_APPEND, 0666);
+	if (out_fd < 0) {
+		ERROR("error re-opening log file: %s\n", out_filename);
+		return -1;
+	}
+
+	err_fd = xopen(err_filename, O_CREAT | O_WRONLY | O_APPEND, 0666);
+	if (err_fd < 0) {
+		ERROR("error re-opening error file: %s\n", err_filename);
+		return -1;
+	}
+
+	umask(prev);
+
+	redirect_logs();
+	DEBUG("Done cycling log files\n");
+	return 0;
+}
+
+void close_log_files(void)
+{
+	if (stdout_mode)
+		return;
+	assert(out_fd > 0);
+	assert(err_fd > 0);
+	xclose(out_fd);
+	xclose(err_fd);
+}
+

src/log.h

@@ -29,28 +29,28 @@
 #define LOG_LEVEL_SECURE	1
 #define LOG_LEVEL_DEBUG		2
 
-extern int logLevel;
+#ifndef NDEBUG
-extern short warningFlushed;
+  mpd_printf void DEBUG(const char *fmt, ...);
+#else
+  static inline void DEBUG(const char *fmt, ...) { }
+#endif
 
-#define ERROR(...) fdprintf(STDERR_FILENO, __VA_ARGS__)
+mpd_printf void ERROR(const char *fmt, ...);
+mpd_printf void LOG(const char *fmt, ...);
+mpd_printf void SECURE(const char *fmt, ...);
+mpd_printf void WARNING(const char *fmt, ...);
+mpd_printf void FATAL(const char *fmt, ...);
 
-#define LOG(...) fdprintf(STDOUT_FILENO,  __VA_ARGS__)
+void initLog(const int verbose);
 
-#define SECURE(...) if(logLevel>=LOG_LEVEL_SECURE) \
+void setup_log_output(const int use_stdout);
-				fdprintf(STDOUT_FILENO, __VA_ARGS__)
 
-#define DEBUG(...) if(logLevel>=LOG_LEVEL_DEBUG) \
+void open_log_files(const int use_stdout);
-				fdprintf(STDOUT_FILENO, __VA_ARGS__)
 
-#define WARNING(...) { \
+int cycle_log_files(void);
-	if(warningFlushed) fdprintf(STDERR_FILENO, __VA_ARGS__); \
-	else bufferWarning(__VA_ARGS__); \
-}
 
-void initLog();
+void close_log_files(void);
-
-void bufferWarning(char *format, ...);
 
 void flushWarningLog();
 
-#endif
+#endif /* LOG_H */

src/main.c

@@ -68,6 +68,7 @@ typedef struct _Options {
 	int stdOutput;
 	int createDB;
 	int updateDB;
+	int verbose;
 } Options;
 
 /* 
@@ -186,7 +187,7 @@ static void parseOptions(int argc, char **argv, Options * options)
 					options->createDB = -1;
 					argcLeft--;
 				} else if (strcmp(argv[i], "--verbose") == 0) {
-					logLevel = LOG_LEVEL_DEBUG;
+					options->verbose = 1;
 					argcLeft--;
 				} else if (strcmp(argv[i], "--version") == 0) {
 					version();
@@ -284,36 +285,6 @@ static void changeToUser(void)
 	}
 }
 
-static void openLogFiles(Options * options, FILE ** out, FILE ** err)
-{
-	ConfigParam *logParam = parseConfigFilePath(CONF_LOG_FILE, 1);
-	ConfigParam *errorParam = parseConfigFilePath(CONF_ERROR_FILE, 1);
-
-	mode_t prev;
-
-	if (options->stdOutput) {
-		flushWarningLog();
-		return;
-	}
-
-	/* be sure to create log files w/ rw permissions */
-	prev = umask(0066);
-
-	if (NULL == (*out = fopen(logParam->value, "a"))) {
-		ERROR("problem opening log file \"%s\" (config line %i) for "
-		      "writing\n", logParam->value, logParam->line);
-		exit(EXIT_FAILURE);
-	}
-
-	if (NULL == (*err = fopen(errorParam->value, "a"))) {
-		ERROR("problem opening error file \"%s\" (config line %i) for "
-		      "writing\n", errorParam->value, errorParam->line);
-		exit(EXIT_FAILURE);
-	}
-
-	umask(prev);
-}
-
 static void openDB(Options * options, char *argv0)
 {
 	if (options->createDB > 0 || readDirectoryDB() < 0) {
@@ -369,7 +340,7 @@ static void startMainProcess(void)
 		kill(mainPid, SIGTERM);
 		waitpid(mainPid, NULL, 0);
 		finishConf();
-		myfprintfCloseLogFile();
+		close_log_files();
 		exit(EXIT_SUCCESS);
 
 	} else if (pid < 0) {
@@ -441,43 +412,6 @@ static void daemonize(Options * options)
 	}
 }
 
-static void setupLogOutput(Options * options, FILE * out, FILE * err)
-{
-	if (!options->stdOutput) {
-		fflush(NULL);
-
-		if (dup2(fileno(out), STDOUT_FILENO) < 0) {
-			fprintf(err, "problems dup2 stdout : %s\n",
-				  strerror(errno));
-			exit(EXIT_FAILURE);
-		}
-
-		if (dup2(fileno(err), STDERR_FILENO) < 0) {
-			fprintf(err, "problems dup2 stderr : %s\n",
-				  strerror(errno));
-			exit(EXIT_FAILURE);
-		}
-
-		myfprintfStdLogMode(out, err);
-	}
-	flushWarningLog();
-
-	/* lets redirect stdin to dev null as a work around for libao bug */
-	{
-		int fd = open("/dev/null", O_RDONLY);
-		if (fd < 0) {
-			ERROR("not able to open /dev/null to redirect stdin: "
-			      "%s\n", strerror(errno));
-			exit(EXIT_FAILURE);
-		}
-		if (dup2(fd, STDIN_FILENO) < 0) {
-			ERROR("problems dup2's stdin for redirection: "
-			      "%s\n", strerror(errno));
-			exit(EXIT_FAILURE);
-		}
-	}
-}
-
 static void cleanUpPidFile(void)
 {
 	ConfigParam *pidFileParam = parseConfigFilePath(CONF_PID_FILE, 0);
@@ -523,8 +457,6 @@ static void killFromPidFile(char *cmd, int killOption)
 
 int main(int argc, char *argv[])
 {
-	FILE *out = NULL;
-	FILE *err = NULL;
 	Options options;
 
 	closeAllFDs();
@@ -538,14 +470,14 @@ int main(int argc, char *argv[])
 
 	initStats();
 	initTagConfig();
-	initLog();
+	initLog(options.verbose);
 
 	if (options.createDB <= 0 && !options.updateDB)
 		listenOnPort();
 
 	changeToUser();
 
-	openLogFiles(&options, &out, &err);
+	open_log_files(options.stdOutput);
 
 	initPlayerData();
 
@@ -560,7 +492,7 @@ int main(int argc, char *argv[])
 	daemonize(&options);
 
 	initSigHandlers();
-	setupLogOutput(&options, out, err);
+	setup_log_output(options.stdOutput);
 	startMainProcess();
 	/* This is the main process which has
 	 * been forked from the master process.
@@ -613,6 +545,6 @@ int main(int argc, char *argv[])
 	cleanUpPidFile();
 	finishConf();
 
-	myfprintfCloseLogFile();
+	close_log_files();
 	return EXIT_SUCCESS;
 }

src/myfprintf.c

@@ -33,12 +33,6 @@
 
 #define BUFFER_LENGTH	MAXPATHLEN+1024
 
-static int myfprintf_stdLogMode = 0;
-static FILE *myfprintf_out;
-static FILE *myfprintf_err;
-static char *myfprintf_outFilename;
-static char *myfprintf_errFilename;
-
 static void blockingWrite(const int fd, const char *string, size_t len)
 {
 	while (len) {
@@ -62,7 +56,9 @@ void vfdprintf(const int fd, const char *fmt, va_list args)
 
 	vsnprintf(buf, BUFFER_LENGTH, fmt, args);
 	len = strlen(buf);
-	if (interfacePrintWithFD(fd, buf, len) < 0)
+	if (fd == STDERR_FILENO ||
+	    fd == STDOUT_FILENO ||
+	    interfacePrintWithFD(fd, buf, len) < 0)
 		blockingWrite(fd, buf, len);
 }
 
@@ -74,47 +70,3 @@ mpd_fprintf void fdprintf(const int fd, const char *fmt, ...)
 	va_end(args);
 }
 
-void myfprintfStdLogMode(FILE * out, FILE * err)
-{
-	myfprintf_stdLogMode = 1;
-	myfprintf_out = out;
-	myfprintf_err = err;
-	myfprintf_outFilename = parseConfigFilePath(CONF_LOG_FILE, 1)->value;
-	myfprintf_errFilename = parseConfigFilePath(CONF_ERROR_FILE, 1)->value;
-}
-
-int myfprintfCloseAndOpenLogFile(void)
-{
-	if (myfprintf_stdLogMode) {
-		while (fclose(myfprintf_out) < 0 && errno == EINTR) ;
-		while (fclose(myfprintf_err) < 0 && errno == EINTR) ;
-		while ((myfprintf_out =
-			fopen(myfprintf_outFilename, "a+")) == NULL
-		       && errno == EINTR) ;
-		if (!myfprintf_out) {
-			ERROR("error re-opening log file: %s\n",
-			      myfprintf_outFilename);
-			return -1;
-		}
-		while ((myfprintf_err =
-			fopen(myfprintf_errFilename, "a+")) == NULL
-		       && errno == EINTR) ;
-		if (!myfprintf_err) {
-			ERROR("error re-opening error file: %s\n",
-			      myfprintf_errFilename);
-			return -1;
-		}
-		while (dup2(fileno(myfprintf_out), 1) < 0 && errno == EINTR) ;
-		while (dup2(fileno(myfprintf_err), 2) < 0 && errno == EINTR) ;
-	}
-
-	return 0;
-}
-
-void myfprintfCloseLogFile(void)
-{
-	if (myfprintf_stdLogMode) {
-		while (fclose(myfprintf_out) < 0 && errno == EINTR) ;
-		while (fclose(myfprintf_err) < 0 && errno == EINTR) ;
-	}
-}

src/myfprintf.h

@@ -25,12 +25,7 @@
 #include <stdarg.h>
 #include <stdio.h>
 
-void myfprintfStdLogMode(FILE * out, FILE * err);
-
 mpd_fprintf void fdprintf(const int fd, const char *fmt, ...);
 void vfdprintf(const int fd, const char *fmt, va_list arglist);
 
-int myfprintfCloseAndOpenLogFile();
-
-void myfprintfCloseLogFile();
 #endif

src/player.c

@@ -136,7 +136,7 @@ int playerInitReal()
 				pc->queueLockState = PLAYER_QUEUE_UNLOCKED;
 				pc->unlockQueue = 0;
 			} else if (pc->cycleLogFiles) {
-				myfprintfCloseAndOpenLogFile();
+				cycle_log_files();
 				pc->cycleLogFiles = 0;
 			} else
 				my_usleep(10000);

src/sig_handlers.c

@@ -79,7 +79,7 @@ int handlePendingSignals()
 			readDirectoryDB();
 			playlistVersionChange();
 		}
-		if (myfprintfCloseAndOpenLogFile() < 0)
+		if (cycle_log_files() < 0)
 			return COMMAND_RETURN_KILL;
 		playerCycleLogFiles();
 	}