From: Tim-Philipp Müller <tim@centricular.com>
Date: Wed, 11 Apr 2018 18:56:01 +0000 (+0100)
Subject: gstdebug: fix occasional deadlocks on windows when outputting debug logging
X-Git-Tag: 1.16.2~417
X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=ae612551fa0a2378bfb71eb03611dc6c0861ee7a;p=platform%2Fupstream%2Fgstreamer.git

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
---

diff --git a/gst/gstinfo.c b/gst/gstinfo.c
index 1556684..2f6a630 100644
--- a/gst/gstinfo.c
+++ b/gst/gstinfo.c
@@ -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
   }