gstdebug: fix occasional deadlocks on windows when outputting debug logging

When outputting debug logs on Windows, some sections are protected
with a non-recursive lock. Turns out though that gst_debug_message_get()
might indirectly, via our printf format extensions, call code which
in turn would try to log something when it can't handle something. If
that happens we end up in gst_debug_log_default() again recursively and
try to again take the lock that's already taken, thus deadlocking.

Format the debug message string outside of the critical section
instead to avoid this.

https://bugzilla.gnome.org/show_bug.cgi?id=784382
This commit is contained in:
Tim-Philipp Müller 2018-04-11 19:56:01 +01:00
parent 92887d4767
commit ee0619ec66

View file

@ -1137,9 +1137,19 @@ gst_debug_log_default (GstDebugCategory * category, GstDebugLevel level,
GstClockTime elapsed;
gchar *obj = NULL;
GstDebugColorMode color_mode;
const gchar *message_str;
FILE *log_file = user_data ? user_data : stderr;
gchar c;
/* Get message string first because printing it might call into our custom
* printf format extension mechanism which in turn might log something, e.g.
* from inside gst_structure_to_string() when something can't be serialised.
* This means we either need to do this outside of any critical section or
* use a recursive lock instead. As we always need the message string in all
* code paths, we might just as well get it here first thing and outside of
* the win_print_mutex critical section. */
message_str = gst_debug_message_get (message);
/* __FILE__ might be a file name or an absolute path or a
* relative path, irrespective of the exact compiler used,
* in which case we want to shorten it to the filename for
@ -1186,7 +1196,7 @@ gst_debug_log_default (GstDebugCategory * category, GstDebugLevel level,
pidcolor, pid, clear, g_thread_self (), levelcolor,
gst_debug_level_get_name (level), clear, color,
gst_debug_category_get_name (category), file, line, function, obj,
clear, gst_debug_message_get (message));
clear, message_str);
fflush (log_file);
#undef PRINT_FMT
g_free (color);
@ -1221,7 +1231,7 @@ gst_debug_log_default (GstDebugCategory * category, GstDebugLevel level,
fflush (log_file);
/* message */
SET_COLOR (clear);
fprintf (log_file, " %s\n", gst_debug_message_get (message));
fprintf (log_file, " %s\n", message_str);
fflush (log_file);
}
g_mutex_unlock (&win_print_mutex);
@ -1232,7 +1242,7 @@ gst_debug_log_default (GstDebugCategory * category, GstDebugLevel level,
fprintf (log_file, "%" GST_TIME_FORMAT PRINT_FMT, GST_TIME_ARGS (elapsed),
pid, g_thread_self (), gst_debug_level_get_name (level),
gst_debug_category_get_name (category), file, line, function, obj,
gst_debug_message_get (message));
message_str);
fflush (log_file);
#undef PRINT_FMT
}