After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 765456 - vtdec: Strange bug re-encoding video with GST 1.8.1 on Mac OS 10.10
vtdec: Strange bug re-encoding video with GST 1.8.1 on Mac OS 10.10
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins-bad
1.8.1
Other Mac OS
: Normal normal
: 1.8.2
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2016-04-23 08:51 UTC by Andy Robinson
Modified: 2016-05-06 06:49 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Log with backtrace of crash. (10.15 KB, text/plain)
2016-04-23 16:03 UTC, Andy Robinson
  Details
Debug=6 log of not-negotiated case. (556.66 KB, application/zip)
2016-04-27 11:25 UTC, Andy Robinson
  Details
Proposed fix (2.92 KB, patch)
2016-05-04 01:57 UTC, Alessandro Decina
needs-work Details | Review
decodebin: an element can negotiate before we block it (2.74 KB, patch)
2016-05-04 07:14 UTC, Sebastian Dröge (slomo)
committed Details | Review

Description Andy Robinson 2016-04-23 08:51:59 UTC
GST 1.8.1 on Mac OS 10.10

Here are commands for copy-and-copy-again of a video:

gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4

gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4

On Windows 10, GST 1.8.1, this works fine. But on Mac OS 10.10 the first copy succeeds but the second one produces this:

Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Redistribute latency...
Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0";
ERROR: from element /GstPipeline:pipeline0/GstDecodeBin:decodebin0/GstQTDemux:qtdemux0: GStreamer encountered a general stream error.
Additional debug info:
qtdemux.c(5423): gst_qtdemux_loop (): /GstPipeline:pipeline0/GstDecodeBin:decodebin0/GstQTDemux:qtdemux0:
streaming stopped, reason not-negotiated
ERROR: pipeline doesn't want to preroll.
Setting pipeline to NULL ...
Freeing pipeline ...

For completeness I have placed the source file Bear.wmv here:
http://www.seventhstring.com/other2/Bear.wmv
though my impression is that this problem happens with pretty much any video.

Using GST 1.6.3 there is again no problem on Windows but on Mac both copies appear to succeed: however the second copy won't play, QuickTime Player says the file is corrupt.

Andy Robinson
Comment 1 Tim-Philipp Müller 2016-04-23 10:20:19 UTC
Please try:

 gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4

and

 gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4
Comment 2 Sebastian Dröge (slomo) 2016-04-23 10:41:53 UTC
And

> gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink

My guess is that this is related to vtdec usage on OSX. Can you also get a debug log with GST_DEBUG=3,vtdec:6 if the above already fails?
Comment 3 Andy Robinson 2016-04-23 11:17:23 UTC
These two both work fine:
gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4
gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4

This fails as before on the 2nd copy:
gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out1.mp4
gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4

To my surprise this works, using videotestsrc instead of a video file, both copies are good:
gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4
gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4

This crashes on the 2nd command:
gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4
gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink

Here is the output from the 2nd command:
gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Redistribute latency...
Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0";
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Caught SIGSEGV
exec gdb failed: No such file or directory
Spinning.  Please run 'gdb gst-launch-1.0 1895' to continue debugging, Ctrl-C to quit, or Ctrl-\ to dump core.

And here is that second command again, with debug log:
Andys-MacBook-Pro:Temp1 andy$ export GST_DEBUG=3,vtdec:6
Andys-MacBook-Pro:Temp1 andy$ gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink
Setting pipeline to PAUSED ...
0:00:00.021891000  1909 0x7fe9badb1890 WARN                 basesrc gstbasesrc.c:3486:void gst_base_src_start_complete(GstBaseSrc *, GstFlowReturn):<filesrc0> pad not activated yet
Pipeline is PREROLLING ...
0:00:00.028758000  1909 0x7fe9bd005d40 WARN                 qtdemux qtdemux.c:2642:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 1
0:00:00.028914000  1909 0x7fe9bd005d40 WARN                 basesrc gstbasesrc.c:2396:gboolean gst_base_src_update_length(GstBaseSrc *, guint64, guint *, gboolean):<filesrc0> processing at or past EOS
0:00:00.034947000  1909 0x7fe9bc00c8a0 DEBUG                  vtdec vtdec.c:179:gst_vtdec_start:<vtdechw0> start
0:00:00.034971000  1909 0x7fe9bc00c8a0 FIXME           videodecoder gstvideodecoder.c:1057:GstFlowReturn gst_video_decoder_drain_out(GstVideoDecoder *, gboolean):<vtdechw0> Sub-class should implement drain()
0:00:00.035147000  1909 0x7fe9bc00c8a0 DEBUG                  vtdec vtdec.c:318:gst_vtdec_set_format:<vtdechw0> set_format
0:00:00.035168000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:941:compute_h264_decode_picture_buffer_length:<vtdechw0> parsed profile 100, level 30
0:00:00.035186000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:977:gst_vtdec_set_latency:<vtdechw0> setting latency frames:6 time:0:00:00.200199996
0:00:00.035286000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:271:gst_vtdec_negotiate:<vtdechw0> negotiated output format video/x-raw(memory:GLMemory), format=(string)NV12, width=(int)720, height=(int)480, interlace-mode=(string)progressive, pixel-aspect-ratio=(fraction)8/9, chroma-site=(string)jpeg, colorimetry=(string)bt601, framerate=(fraction)30000/1001, texture-target=(string)rectangle
Redistribute latency...
0:00:00.056271000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:987:gst_vtdec_set_context:<vtdechw0> setting context gst.gl.GLDisplay
Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0";
0:00:00.066304000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:289:gst_vtdec_negotiate:<vtdechw0> pushing textures, context 0x7fe9bb8139d0 old context 0x0
0:00:00.066570000  1909 0x7fe9bc00c8a0 FIXME           videodecoder gstvideodecoder.c:1057:GstFlowReturn gst_video_decoder_drain_out(GstVideoDecoder *, gboolean):<vtdechw0> Sub-class should implement drain()
0:00:00.067007000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 0
0:00:00.067859000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 0
0:00:00.067935000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 1
0:00:00.068243000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 1
0:00:00.068288000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 2
0:00:00.068552000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 2
0:00:00.068597000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 3
0:00:00.068803000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004d70 0 and VT buffer 0x7fe9bac80bb0
0:00:00.069107000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 3
0:00:00.069149000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 4
0:00:00.069441000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07a660 1 and VT buffer 0x7fe9bac90280
0:00:00.069473000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 4
0:00:00.069541000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 5
0:00:00.069881000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004e80 2 and VT buffer 0x7fe9bac908b0
0:00:00.069919000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 5
0:00:00.069981000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 6
0:00:00.070343000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004c60 3 and VT buffer 0x7fe9bc832df0
0:00:00.070379000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 6
0:00:00.070467000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 7
0:00:00.070695000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07a990 4 and VT buffer 0x7fe9bae31ff0
0:00:00.070923000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 7
0:00:00.071001000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 8
0:00:00.071445000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07add0 5 and VT buffer 0x7fe9bca07b80
0:00:00.071486000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 8
0:00:00.071644000  1909 0x7fe9bc00c8a0 LOG                    vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 9
0:00:00.071826000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf0081a0 6 and VT buffer 0x7fe9bc9015f0
0:00:00.072318000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf0084d0 7 and VT buffer 0x7fe9bc832bf0
0:00:00.072684000  1909 0x7fe9badde040 LOG                    vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07abb0 8 and VT buffer 0x7fe9bae33c20

(gst-launch-1.0:1909): GStreamer-CRITICAL **: gst_debug_log_valist: assertion 'category != NULL' failed
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
0:00:00.103659000  1909 0x7fe9bc00c8a0 INFO                   vtdec vtdec.c:289:gst_vtdec_negotiate:<vtdechw0> pushing textures, context 0x7fe9bb8139d0 old context 0x7fe9bb8139d0
Caught SIGSEGV
exec gdb failed: No such file or directory
Spinning.  Please run 'gdb gst-launch-1.0 1909' to continue debugging, Ctrl-C to quit, or Ctrl-\ to dump core.
Comment 4 Sebastian Dröge (slomo) 2016-04-23 15:07:30 UTC
Ok so it's clearly related to the decoding with vtdec and not with the encoding afterwards (vtdec is used for H264 but not for WMV).

Can you get a backtrace of the crash with the last pipeline, with gdb or lldb?


It's also interesting that the case of decoding, reencoding and muxing errors out with a not-negotiated. Can you get a GST_DEBUG=6 log for that one?


Please attach all debug logs to the bug, not inline into comments. Backtraces should go inline into comments though.
Comment 5 Andy Robinson 2016-04-23 16:02:37 UTC
I've done a log with backtrace of the crash in bt1.txt which I willl attach. Here is the backtrace part of it:
  * frame #0: 0x00007fff978f035a libsystem_platform.dylib`OSAtomicAdd32Barrier$VARIANT$mp + 2
    frame #1: 0x00007fff952b8709 IOSurface`IOSurfaceClientDecrementUseCount + 26
    frame #2: 0x0000000105f99047 libgstapplemedia.so`_io_surface_memory_destroy + 39
    frame #3: 0x0000000105fdaaa1 libgstgl-1.0.0.dylib`_destroy_gl_objects + 33
    frame #4: 0x0000000105ff033d libgstgl-1.0.0.dylib`_run_message_sync + 29
    frame #5: 0x0000000105ff02f7 libgstgl-1.0.0.dylib`_run_message_async + 23
    frame #6: 0x000000010021f9c6 libglib-2.0.0.dylib`g_main_context_dispatch + 326
    frame #7: 0x000000010021fcf4 libglib-2.0.0.dylib`g_main_context_iterate + 420
    frame #8: 0x000000010022001f libglib-2.0.0.dylib`g_main_loop_run + 223
    frame #9: 0x0000000105fd76af libgstgl-1.0.0.dylib`gst_gl_context_create_thread + 575
    frame #10: 0x000000010024744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #11: 0x00007fff9790905a libsystem_pthread.dylib`_pthread_body + 131
    frame #12: 0x00007fff97908fd7 libsystem_pthread.dylib`_pthread_start + 176
    frame #13: 0x00007fff979063ed libsystem_pthread.dylib`thread_start + 13

The GST_DEBUG=6 log for the not-negotiated case is 42 MB, is it appropriate to attach something that big?
Comment 6 Andy Robinson 2016-04-23 16:03:31 UTC
Created attachment 326597 [details]
Log with backtrace of crash.
Comment 7 Sebastian Dröge (slomo) 2016-04-25 06:11:03 UTC
Please compress the debug log and if it's still too large, upload it to something like dropbox.

The crash looks like some reference counting problem with the IOSurfaces
Comment 8 Andy Robinson 2016-04-27 11:23:59 UTC
I've just done the GST_DEBUG=6 again and for some reason the output is smaller - only 9 MB, or 500 KB compressed, so I thing that means I can upload it here...
(Result is still "not-negotiated").
Comment 9 Andy Robinson 2016-04-27 11:25:43 UTC
Created attachment 326853 [details]
Debug=6 log of not-negotiated case.
Comment 10 Alessandro Decina 2016-05-04 01:57:26 UTC
Created attachment 327259 [details] [review]
Proposed fix

As discussed on IRC, the problem is that vtdec configures GLMemory by default, then while it can renegotiate to sysmem, because decodebin exposes the pad too late renegotiation can't happen and we get not-negotiated.

This change fixes it for me. Someone please double check before I commit.

(Separately I now already made vtdec default to sysmem).
Comment 11 Sebastian Dröge (slomo) 2016-05-04 07:13:03 UTC
Review of attachment 327259 [details] [review]:

Makes sense to me but seems like if it caused any problems before then this will still cause problems in a racy way. We might expose the pad before the first buffer, or not, depending on timing.

::: gst/playback/gstdecodebin2.c
@@ +5064,3 @@
+
+  caps = gst_pad_get_current_caps (GST_PAD_CAST (endpad));
+  has_fixed_caps = gst_caps_is_fixed (caps);

Current caps are always fixed, they might just be NULL too. You can just check gst_pad_has_current_caps() here instead (and calling gst_caps_is_fixed(NULL) gives an assertion).
Comment 12 Sebastian Dröge (slomo) 2016-05-04 07:14:01 UTC
Created attachment 327267 [details] [review]
decodebin: an element can negotiate before we block it

When we initialize an element in decodebin, we 1) set it to PAUSED and
push sticky events on its sinkpad to trigger negotiation 2) block its
src pad(s) to detect CAPS events. We can't block before 1) as that
would lead to a deadlock.

It's possible (and common) tho that an element configures its srcpad
during 1) and before 2). Therefore before this change we would
typically block and expose an element's pad only once the element
output its first buffer, triggering sticky events to be resent. One
consequence of this behaviour is that it sometimes broke
renegotiation.

With this change now we consider a pad ready to be exposed when it's
->blocked or has fixed caps (which were set before we could block it).
Comment 13 Sebastian Dröge (slomo) 2016-05-04 07:16:22 UTC
The original bug should be fixed by https://cgit.freedesktop.org/gstreamer/gst-plugins-bad/commit/?id=5228238715a3d73bbfe9a7de1c02941096e95576
Comment 14 Sebastian Dröge (slomo) 2016-05-04 07:25:57 UTC
Attachment 327267 [details] pushed as fe4e9bb - decodebin: an element can negotiate before we block it
Comment 15 Sebastian Dröge (slomo) 2016-05-04 07:26:35 UTC
gst-validate is also happy about this, so let's get it in.

Alessandro, the change in gst-plugins-bad should also go into 1.8 I assume?
Comment 16 Sebastian Dröge (slomo) 2016-05-06 06:49:14 UTC
https://cgit.freedesktop.org/gstreamer/gst-plugins-bad/commit/?id=5228238715a3d73bbfe9a7de1c02941096e95576 is backported to 1.8.2 now