Issue #26: Lock mutex accurately, the approach wasnt thread safe

Author: za-arthur

src/pg_probackup.c

@@ -202,7 +202,11 @@ main(int argc, char *argv[])
 	/*
 	 * Save main thread's tid. It is used call exit() in case of errors.
 	 */
+#ifdef WIN32
+	main_tid = GetCurrentThreadId();
+#else
 	main_tid = pthread_self();
+#endif
 
 	/* Parse subcommands and non-subcommand options */
 	if (argc > 1)

src/utils/logger.c

@@ -50,6 +50,8 @@ void pg_log(eLogType type, const char *fmt,...) pg_attribute_printf(2, 3);
 
 static void elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 						  pg_attribute_printf(3, 0);
+static void elog_stderr(int elevel, const char *fmt, ...)
+						pg_attribute_printf(2, 3);
 
 /* Functions to work with log files */
 static void open_logfile(FILE **file, const char *filename_format);
@@ -63,8 +65,8 @@ static FILE *log_file = NULL;
 static FILE *error_log_file = NULL;
 
 static bool exit_hook_registered = false;
-/* Logging to file is in progress */
-static bool logging_to_file = false;
+/* Logging of the current thread is in progress */
+static bool loggin_in_progress = false;
 
 static pthread_mutex_t log_file_mutex = PTHREAD_MUTEX_INITIALIZER;
 
@@ -111,11 +113,37 @@ write_elevel(FILE *stream, int elevel)
 			fputs("PANIC: ", stream);
 			break;
 		default:
-			elog(ERROR, "invalid logging level: %d", elevel);
+			elog_stderr(ERROR, "invalid logging level: %d", elevel);
 			break;
 	}
 }
 
+/*
+ * Exit with code if it is an error.
+ * Check for in_cleanup flag to avoid deadlock in case of ERROR in cleanup
+ * routines.
+ */
+static void
+exit_if_necessary(int elevel)
+{
+	if (elevel > WARNING && !in_cleanup)
+	{
+		/* Interrupt other possible routines */
+		interrupted = true;
+
+		/* If this is not the main thread then don't call exit() */
+#ifdef WIN32
+		if (main_tid != GetCurrentThreadId())
+			ExitThread(elevel);
+#else
+		if (!pthread_equal(main_tid, pthread_self()))
+			pthread_exit(NULL);
+#endif
+		else
+			exit(elevel);
+	}
+}
+
 /*
  * Logs to stderr or to log file and exit if ERROR or FATAL.
  *
@@ -132,18 +160,19 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 	time_t		log_time = (time_t) time(NULL);
 	char		strfbuf[128];
 
-	write_to_file = !logging_to_file && elevel >= LOG_LEVEL_FILE &&
+	write_to_file = elevel >= LOG_LEVEL_FILE && log_path[0] != '\0';
+	write_to_error_log = elevel >= ERROR && error_log_filename &&
 		log_path[0] != '\0';
-	write_to_error_log = !logging_to_file && elevel >= ERROR &&
-		error_log_filename && log_path[0] != '\0';
 	write_to_stderr = elevel >= LOG_LEVEL_CONSOLE && !file_only;
 
 	/*
-	 * There is no need to lock if this is elog() from upper elog() and
-	 * logging is not initialized.
+	 * There is no need to lock if this is elog() from upper elog().
 	 */
-	if (write_to_file || write_to_error_log || write_to_stderr)
+	if (!loggin_in_progress)
+	{
 		pthread_mutex_lock(&log_file_mutex);
+		loggin_in_progress = true;
+	}
 
 	/* We need copy args only if we need write to error log file */
 	if (write_to_error_log)
@@ -166,8 +195,6 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 	 */
 	if (write_to_file)
 	{
-		logging_to_file = true;
-
 		if (log_file == NULL)
 		{
 			if (log_filename == NULL)
@@ -182,8 +209,6 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 		vfprintf(log_file, fmt, args);
 		fputc('\n', log_file);
 		fflush(log_file);
-
-		logging_to_file = false;
 	}
 
 	/*
@@ -193,8 +218,6 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 	 */
 	if (write_to_error_log)
 	{
-		logging_to_file = true;
-
 		if (error_log_file == NULL)
 			open_logfile(&error_log_file, error_log_filename);
 
@@ -205,7 +228,6 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 		fputc('\n', error_log_file);
 		fflush(error_log_file);
 
-		logging_to_file = false;
 		va_end(error_args);
 	}
 
@@ -228,25 +250,41 @@ elog_internal(int elevel, bool file_only, const char *fmt, va_list args)
 			va_end(std_args);
 	}
 
-	if (write_to_file || write_to_error_log || write_to_stderr)
+	if (loggin_in_progress)
+	{
 		pthread_mutex_unlock(&log_file_mutex);
+		loggin_in_progress = false;
+	}
+
+	exit_if_necessary(elevel);
+}
+
+/*
+ * Log only to stderr. It is called only within elog_internal() when another
+ * logging already was started.
+ */
+static void
+elog_stderr(int elevel, const char *fmt, ...)
+{
+	va_list		args;
 
 	/*
-	 * Exit with code if it is an error.
-	 * Check for in_cleanup flag to avoid deadlock in case of ERROR in cleanup
-	 * routines.
+	 * Do not log message if severity level is less than log_level.
+	 * It is the little optimisation to put it here not in elog_internal().
 	 */
-	if (elevel > WARNING && !in_cleanup)
-	{
-		/* Interrupt other possible routines */
-		interrupted = true;
+	if (elevel < LOG_LEVEL_CONSOLE && elevel < ERROR)
+		return;
 
-		/* If this is not the main thread then don't call exit() */
-		if (!pthread_equal(main_tid, pthread_self()))
-			pthread_exit(NULL);
-		else
-			exit(elevel);
-	}
+	va_start(args, fmt);
+
+	write_elevel(stderr, elevel);
+	vfprintf(stderr, fmt, args);
+	fputc('\n', stderr);
+	fflush(stderr);
+
+	va_end(args);
+
+	exit_if_necessary(elevel);
 }
 
 /*
@@ -417,7 +455,7 @@ logfile_getname(const char *format, time_t timestamp)
 	struct tm  *tm = localtime(&timestamp);
 
 	if (log_path[0] == '\0')
-		elog(ERROR, "logging path is not set");
+		elog_stderr(ERROR, "logging path is not set");
 
 	filename = (char *) palloc(MAXPGPATH);
 
@@ -427,7 +465,7 @@ logfile_getname(const char *format, time_t timestamp)
 
 	/* Treat log_filename as a strftime pattern */
 	if (strftime(filename + len, MAXPGPATH - len, format, tm) <= 0)
-		elog(ERROR, "strftime(%s) failed: %s", format, strerror(errno));
+		elog_stderr(ERROR, "strftime(%s) failed: %s", format, strerror(errno));
 
 	return filename;
 }
@@ -453,8 +491,8 @@ logfile_open(const char *filename, const char *mode)
 	{
 		int			save_errno = errno;
 
-		elog(FATAL, "could not open log file \"%s\": %s",
-			 filename, strerror(errno));
+		elog_stderr(FATAL, "could not open log file \"%s\": %s",
+					filename, strerror(errno));
 		errno = save_errno;
 	}
 
@@ -488,8 +526,8 @@ open_logfile(FILE **file, const char *filename_format)
 			goto logfile_open;
 		}
 		else
-			elog(ERROR, "cannot stat log file \"%s\": %s",
-				 filename, strerror(errno));
+			elog_stderr(ERROR, "cannot stat log file \"%s\": %s",
+						filename, strerror(errno));
 	}
 	/* Found log file "filename" */
 	logfile_exists = true;
@@ -505,35 +543,35 @@ open_logfile(FILE **file, const char *filename_format)
 			if (stat(control, &control_st) == -1)
 			{
 				if (errno != ENOENT)
-					elog(ERROR, "cannot stat rotation file \"%s\": %s",
-						 control, strerror(errno));
+					elog_stderr(ERROR, "cannot stat rotation file \"%s\": %s",
+								control, strerror(errno));
 			}
 			else
 			{
 				char		buf[1024];
 
 				control_file = fopen(control, "r");
 				if (control_file == NULL)
-					elog(ERROR, "cannot open rotation file \"%s\": %s",
-						 control, strerror(errno));
+					elog_stderr(ERROR, "cannot open rotation file \"%s\": %s",
+								control, strerror(errno));
 
 				if (fgets(buf, lengthof(buf), control_file))
 				{
 					time_t		creation_time;
 
 					if (!parse_int64(buf, (int64 *) &creation_time, 0))
-						elog(ERROR, "rotation file \"%s\" has wrong "
-							 "creation timestamp \"%s\"",
-							 control, buf);
+						elog_stderr(ERROR, "rotation file \"%s\" has wrong "
+									"creation timestamp \"%s\"",
+									control, buf);
 					/* Parsed creation time */
 
 					rotation_requested = (cur_time - creation_time) >
 						/* convert to seconds */
 						log_rotation_age * 60;
 				}
 				else
-					elog(ERROR, "cannot read creation timestamp from "
-						 "rotation file \"%s\"", control);
+					elog_stderr(ERROR, "cannot read creation timestamp from "
+								"rotation file \"%s\"", control);
 
 				fclose(control_file);
 			}
@@ -560,8 +598,8 @@ open_logfile(FILE **file, const char *filename_format)
 
 		control_file = fopen(control, "w");
 		if (control_file == NULL)
-			elog(ERROR, "cannot open rotation file \"%s\": %s",
-				 control, strerror(errno));
+			elog_stderr(ERROR, "cannot open rotation file \"%s\": %s",
+						control, strerror(errno));
 
 		fprintf(control_file, "%ld", timestamp);
 

src/utils/pgut.c

@@ -42,7 +42,11 @@ static char	   *password = NULL;
 bool			prompt_password = true;
 bool			force_password = false;
 
+#ifdef WIN32
+DWORD main_tid = 0;
+#else
 pthread_t main_tid = 0;
+#endif
 
 /* Database connections */
 static PGcancel *volatile cancel_conn = NULL;

src/utils/pgut.h

@@ -95,7 +95,11 @@ extern const char  *PROGRAM_URL;
 extern const char  *PROGRAM_EMAIL;
 
 /* ID of the main thread */
+#ifdef WIN32
+extern DWORD main_tid;
+#else
 extern pthread_t main_tid;
+#endif
 
 extern void	pgut_help(bool details);