GNOME Bugzilla – Bug 625295
[info] regression: doesn't flush output stream after every debug print any longer
Last modified: 2010-07-27 15:19:15 UTC
There is a new element introduced, streamsynchronizer, which is loaded into the playbin2. I am developing a video player using GStreamer. It works on windows and currently is an ActiveX component, embedded in the C# form. I am using GStreamer-winbuilds for it (http://code.google.com/p/ossbuild/). Its SVN Rev. 771 has merged some changes from the master git branch, streamsynchronizer was among them. My player outputs debug messages using GStreaner's debug system and has switched on debug messages from the mpegvideoparse and playbin2 (--gst-debug=player:5,mpegvideoparse:5,playbin2:5) It also extensively uses playbin2 and directdrawsink as a video sink. It has custom g_print_func: static void g_print_func(const gchar *string) { if(!g_strrstr(string,"assertion `mini_object->refcount > 0' failed")) OutputDebugString(string); } This was set with g_set_print_handler((GPrintFunc) g_print_func); I've found, that debug messages are successfully displayed when the playbin2 is in the playing state. When the playbin2 in any other state, they are either not displayed, or displayed with a very big delay. If I put the player to the playing state, I've got lots of messages, which were to display earlier. When I roll back to the rev 770, everything is displayed like a charm. The generated pipelines differ only in that stream synchronizer.
The messages are delayed or are the really printed later? How do you know when they should be printed? Is there some easy way to reproduce this problem, or maybe you could attach two parts of debug logs to show this behaviour.
Created attachment 166590 [details] Modified seek along with VS2008 solution and project The attached files assume that the system has GStreamer-Winbuilds GPL and GStreamer-Winbuilds SDK installed in c:\Gstreamer\
Yes, the messages are printed later. Looks like they are accumulated in a buffer and displayed in a bunch when this buffer fills. For example, when my form issues seek command to the playbin2, it writes some debug info. I was seeing this message right after clicking on the movie progress bar on my form. Here is my seeking function: void gst_player::set_position(gint64 pos) {gboolean r; if(m_player){ if(m_direction>0){ r=gst_element_seek_simple(GST_ELEMENT(m_player), GST_FORMAT_TIME, (GstSeekFlags)(GST_SEEK_FLAG_FLUSH|GST_SEEK_FLAG_KEY_UNIT), pos*GST_MSECOND); }else{ r=gst_element_seek(m_player,-1.0,GST_FORMAT_TIME, (GstSeekFlags)(GST_SEEK_FLAG_FLUSH|GST_SEEK_FLAG_ACCURATE), GST_SEEK_TYPE_SET,0,GST_SEEK_TYPE_SET,pos*GST_MSECOND); } GST_DEBUG("direction=%d, seek to %"G_GINT64_FORMAT" msec, r=%d",m_direction,pos,r); } } Now messages from this function appear later in a bunch of the other functions. Here is my GStreamer initialization code: { /* manually malloc and fill char *argv[] * I have to do this way as this is an ActiveX control, and it doesn't * have command line parameters.*/ // I've also took into account that gst_init changes argc and argv // and saved their copies to correctly free memory. gst_init(&argc,&argv); GST_DEBUG_CATEGORY_INIT (player_category, "player", 0, g_locale_to_utf8("blah-blah-blah",-1,0,0,0)); gst_debug_set_active(TRUE); g_set_print_handler((GPrintFunc) g_print_func); log_handler_id_app=g_log_set_handler (NULL, (GLogLevelFlags)(G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION), G_GNUC_NO_INSTRUMENT (log_function), NULL); log_handler_gstreamer=g_log_set_handler ("GStreamer", (GLogLevelFlags)(G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION), G_GNUC_NO_INSTRUMENT (log_function), NULL); ... } Here, g_print_func is described as static void g_print_func(const gchar *string) { if(!g_strrstr(string,"assertion `mini_object->refcount > 0' failed")) OutputDebugString(string); } And log_function follows: static void log_function(const gchar *log_domain, GLogLevelFlags log_level,const gchar *message,gpointer user_data) { g_print("%s %s %s\n",log_domain,G_STRINGIFY_ARG(log_level),message); } I also tried to modify seek example ($GST_PLUGINS_BASE/tests/examples/seek/seek.c), the modified version is attached. It shows all messages in time. But I failed to redirect all messages to the OutputDebugString, only a small part of them appear
I've set breakpoints in my functions and found that they are called only several times in the beginning of the work, and at the exit.
That's most likely caused by http://cgit.freedesktop.org/gstreamer/gstreamer/commit/?id=9d4caf8d8c6dd0018258fe97451201a3790e6ca8 It removed the flushing of the stream after every print.
This should hopefully fix it. Please re-open if not. Thanks for the bug report. commit 4cecd73c93b0728cd0e4980ed8d0940c93f9129e Author: Tim-Philipp Müller <tim.muller@collabora.co.uk> Date: Mon Jul 26 18:53:57 2010 +0200 info: flush again after every line of debug output g_printerr() used to do this for us. Also use libc's fprintf() functions, to make sure the stderr pointer we use is actually compatible with the libc linked against by GStreamer (which apparently may not always be the same as what GLib is linked against on windows), and we don't need the functionality ensured by g_fprintf(). Fixes #625295.
It doesn't compile. There's missing '}' somewhere in the gstinfo.c I've added one at the line 956.
It doesn't help. My debug output handlers still are not called.
I fixed the compilation in git (hopefully). I'm not entirely sure I understand your issue correctly. What do you expect your debug output handlers to be called with exactly? The GST_DEBUG debug output? That's not going to work any more, see the commit message at http://cgit.freedesktop.org/gstreamer/gstreamer/commit/?id=9d4caf8d8c6dd0018258fe97451201a3790e6ca8 . This is on purpose and there's no intention to "fix" this again (however, this used to go via the glib printerr handler not the glib print handler afaik). If you want to capture the GStreamer debug messages, you will need to set up a handler via gst_debug_add_log_function().
Yes, I want all debug messages to go through OutputDebugString. I've found already gst_debug_add_log_function(). However, I seem to see another bug. Submitting a new bug report.
This is it. gst_debug_remove_log_function doesn't remove default log handler https://bugzilla.gnome.org/show_bug.cgi?id=625396
Ok, let's close this again then. (There may be another issue that needs fixing though, namely that we don't convert the messsage string to the locale encoding any more, g_printerr() did that too, but I don't think that's related to the issue you're having).