Problem processing OGV file

[Bro666]

System bombs. In the Processing panel the follwinfg is displayed

10 	paul 	Ping & Gus, Season 1, Episode 1 OGV 	2013-10-03 04:53 	La copia al almacenamiento público ha fallado. 	{u'keyname': u'thumb'}

And the trace in lazyserver is:

2013-10-03 05:19:59,196 INFO    [paste.httpserver.ThreadPool] kill_hung_threads status: 10 threads (0 working, 10 idle, 0 starting) ave time N/A, max time 0.00sec, killed 0 workers
2013-10-03 05:19:59,576 DEBUG   [mediagoblin.processing.task] Processing <MediaEntry 15: Layout for Linux Magazine Spain #94>
2013-10-03 05:19:59,577 INFO    [mediagoblin.media_types.video.transcoders] Initializing VideoTranscoder...
2013-10-03 05:19:59,584 INFO    [mediagoblin.media_types.video.transcoders] Discovering /var/www/mediagoblin/user_dev/media/queue/media_entries/ffe46464-5f57-4ead-92a4-e2d9ff07134b/S01E01.ogv
2013-10-03 05:19:59,678 INFO    [mediagoblin.media_types.video.transcoders] Terminating MainLoop
2013-10-03 05:19:59,689 INFO    [mediagoblin.media_types.video.transcoders] Discovering...
2013-10-03 05:19:59,703 INFO    [mediagoblin.media_types.video.transcoders] Done
2013-10-03 05:19:59,839 INFO    [mediagoblin.media_types.video.transcoders] Transcoding...
2013-10-03 05:20:00,009 INFO    [mediagoblin.media_types.video.transcoders] 0% done...
2013-10-03 05:20:01,060 INFO    [mediagoblin.media_types.video.transcoders] 5% done...
2013-10-03 05:20:02,075 INFO    [mediagoblin.media_types.video.transcoders] 11% done...
2013-10-03 05:20:03,067 INFO    [mediagoblin.media_types.video.transcoders] 17% done...
2013-10-03 05:20:04,118 INFO    [mediagoblin.media_types.video.transcoders] 23% done...
2013-10-03 05:20:05,122 INFO    [mediagoblin.media_types.video.transcoders] 29% done...
2013-10-03 05:20:06,027 INFO    [mediagoblin.media_types.video.transcoders] 35% done...
2013-10-03 05:20:08,044 INFO    [mediagoblin.media_types.video.transcoders] 41% done...
2013-10-03 05:20:09,055 INFO    [mediagoblin.media_types.video.transcoders] 52% done...
2013-10-03 05:20:10,087 INFO    [mediagoblin.media_types.video.transcoders] 64% done...
2013-10-03 05:20:11,071 INFO    [mediagoblin.media_types.video.transcoders] 70% done...
2013-10-03 05:20:12,128 INFO    [mediagoblin.media_types.video.transcoders] 82% done...
2013-10-03 05:20:13,076 INFO    [mediagoblin.media_types.video.transcoders] 88% done...
2013-10-03 05:20:14,037 INFO    [mediagoblin.media_types.video.transcoders] 100% done...
2013-10-03 05:20:14,041 INFO    [mediagoblin.media_types.video.transcoders] Done
2013-10-03 05:20:14,110 INFO    [mediagoblin.media_types.video.transcoders] Terminating MainLoop
2013-10-03 05:20:14,121 DEBUG   [mediagoblin.media_types.video.processing] Saving medium...
2013-10-03 05:20:14,127 DEBUG   [mediagoblin.media_types.video.processing] Saved medium
2013-10-03 05:20:14,271 INFO    [mediagoblin.media_types.video.transcoders] playbin ready
2013-10-03 05:20:14,271 CRITICA [mediagoblin.media_types.video.transcoders] Could not get any video data from playbin
/var/www/mediagoblin/mediagoblin/media_types/video/transcoders.py:243: DeprecationWarning: integer argument expected, got float
  0)
2013-10-03 05:20:14,342 INFO    [mediagoblin.media_types.video.transcoders] Seek successful, attaching buffer probe
2013-10-03 05:20:14,343 INFO    [mediagoblin.media_types.video.transcoders] Attached buffer probes: {'fakesink5': 1266L}
2013-10-03 05:20:14,344 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,344 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,345 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,347 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,349 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,350 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,351 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,352 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,353 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,353 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,354 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,355 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,355 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,356 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,357 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,358 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,359 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,359 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,361 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,362 INFO    [mediagoblin.media_types.video.transcoders] Already processing thumbnail
2013-10-03 05:20:14,364 ERROR   [mediagoblin.media_types.video.transcoders] thumbnail error: [<GError at 0x782ac80>, 'gsttheoradec.c(1228): theora_handle_data_packet (): /GstPipeline:pipeline5/GstDecodeBin:decodebin30/GstTheoraDec:theoradec14:\nno header sent yet']
2013-10-03 05:20:14,365 ERROR   [mediagoblin.media_types.video.transcoders] thumbnail error: [<GError at 0x782aca0>, 'gstoggdemux.c(4467): gst_ogg_demux_loop (): /GstPipeline:pipeline5/GstDecodeBin:decodebin30/GstOggDemux:oggdemux14:\nstream stopped, reason error']
2013-10-03 05:20:14,366 ERROR   [mediagoblin.media_types.video.transcoders] Thumbnailing failed: [<GError at 0x782ac00>, 'gsttheoradec.c(1228): theora_handle_data_packet (): /GstPipeline:pipeline5/GstDecodeBin:decodebin30/GstTheoraDec:theoradec14:\nno header sent yet']
2013-10-03 05:20:14,387 ERROR   [mediagoblin.media_types.video.transcoders] Thumbnailing failed: [<GError at 0x5bbb0c0>, 'gstoggdemux.c(4467): gst_ogg_demux_loop (): /GstPipeline:pipeline5/GstDecodeBin:decodebin30/GstOggDemux:oggdemux14:\nstream stopped, reason error']
2013-10-03 05:20:14,388 DEBUG   [mediagoblin.media_types.video.processing] Saving thumbnail...

[Christopher Allan Webber]

This should have been ~fixed in the last release. We're more gracious about thumbnailing failures now.

[ayleph]

This issue is marked as fixed and closed, but it's not actually fixed. The error that should be addressed is gsttheoradec.c(1228): theora_handle_data_packet (): ... no header sent yet. This indicates that the decodebin did not properly demux the ogg container [1].

One solution to this issue would be to force ogg demuxing in mediagoblin/media_types/video/transcoders.py; however, this will fail when a non-ogv video is uploaded. Luckily, there's a simple solution: replace decodebin with decodebin2 inside of the thumbnailing pipeline.

Currently, the decoding pipeline looks like this.

mediagoblin/media_types/video/transcoders.py:

pipeline = ''.join([
    'filesrc location="%s" ! decodebin ! ' % self.source_path,
    'ffmpegcolorspace ! videoscale ! ',
    'video/x-raw-rgb,depth=24,bpp=24,pixel-aspect-ratio=1/1',
    ',width={0}'.format(self.width) if self.width else '',
    ',height={0}'.format(self.height) if self.height else '',
    ' ! ',
    'fakesink signal-handoffs=True'])

The better-behaved pipeline looks like this.

mediagoblin/media_types/video/transcoders.py:

pipeline = ''.join([
    'filesrc location="%s" ! decodebin2 ! ' % self.source_path,
    'ffmpegcolorspace ! videoscale ! ',
    'video/x-raw-rgb,depth=24,bpp=24,pixel-aspect-ratio=1/1',
    ',width={0}'.format(self.width) if self.width else '',
    ',height={0}'.format(self.height) if self.height else '',
    ' ! ',
    'fakesink signal-handoffs=True'])

The only difference is this line:

-    'filesrc location="%s" ! decodebin ! ' % self.source_path,
+    'filesrc location="%s" ! decodebin2 ! ' % self.source_path,

References:
[1] ​http://lists.freedesktop.org/archives/gstreamer-devel/2008-September.txt

[ayleph]

I branched off current GMG master and uploaded the fix.

​https://gitorious.org/mediagoblin/aylephs-mediagoblin/commit/19df85773489255fdefbd1ed4ede033048c3588f

[ayleph]

Re-opening the ticket.

[ayleph]

In the IRC discussion below, slomo provides input about the differences between decodebin and decodebin2.

< paroneayea> | ayleph: what's the difference between decodebin and decodebin2 here?
< ayleph> | To be honest, I don't know what the difference is, internally. I just see different behaviour from them.
< ayleph> | Namely, that decodebin doesn't properly handle the theora streams, while decodebin2 does.
< ayleph> | decodebin2 is used elsewhere in the same file; otherwise I wouldn't have known it existed.
< paroneayea> | I wonder if slomo can comment on that :)
...
< slomo> | ayleph, paroneayea: in 0.10, decodebin was deprecated some time around 0.10.30 and replaced by decodebin2. in 1.x there's only decodebin (which is what was decodebin2 before)
< slomo> | ayleph, paroneayea: use decodebin2 in 0.10, and decodebin in 1.x. and use 1.x ;)
< ayleph> | slomo: Thanks for the input. Would you mind if I quote you on the trac ticket?
< slomo> | no, just copy and paste it there

[Christopher Allan Webber]

Seems pretty straightforward! I merged and pushed the branch. Thanks for the fix, ayleph! :)