GNOME Bugzilla – Bug 349436
dvdemux outputs erroneous timestamp/duration when not receiving NEWSEGMENT event
Last modified: 2009-06-15 22:06:31 UTC
If the dvdemux event does not receive a NEWSEGMENT event prior to receiving buffers, its output buffers have obviously wrong timestamp/duration fields. The following pipelines were run with a modified fakesink element that prints some information (including timestamp and duration) for each buffer it receives. The lines starting with "chain *******" are output from fakesink. Also, the dvdemux element was modified to emit a debug message when it receives a NEWSEGMENT event. When using the following pipeline, everything is fine: gst-launch --gst-debug=dvdemux:5 udpsrc port=8000 ! queue ! rtpdvdepay queue-delay=0 ! dvdemux ! fakesink Setting pipeline to PAUSED ... Pipeline is live and does not need PREROLL ... Setting pipeline to PLAYING ... DEBUG (0x631fa0 - 0:00:00.062688000) dvdemux( 7118) gstdvdemux.c(718):gst_dvdemux_handle_sink_event: NEWSEGMENT received New clock: GstSystemClock DEBUG (0x631fa0 - 0:00:04.101093000) dvdemux( 7118) gstdvdemux.c(718):gst_dvdemux_handle_sink_event: NEWSEGMENT received INFO (0x631fa0 - 0:00:04.101560000) dvdemux( 7118) gstdvdemux.c(817):gst_dvdemux_convert_sink_pair: starting conversion of start DEBUG (0x631fa0 - 0:00:04.101587000) dvdemux( 7118) gstdvdemux.c(446):gst_dvdemux_sink_convert:<dvdemux0> 2 -> 3 INFO (0x631fa0 - 0:00:04.101605000) dvdemux( 7118) gstdvdemux.c(448):gst_dvdemux_sink_convert:<dvdemux0> src_value:0, src_format:2, dest_format:3 INFO (0x631fa0 - 0:00:04.101625000) dvdemux( 7118) gstdvdemux.c(504):gst_dvdemux_sink_convert:<dvdemux0> Result : dest_format:3, dest_value:0, res:1 INFO (0x631fa0 - 0:00:04.101641000) dvdemux( 7118) gstdvdemux.c(823):gst_dvdemux_convert_sink_pair: Finished conversion of start: 0 INFO (0x631fa0 - 0:00:04.101664000) dvdemux( 7118) gstdvdemux.c(825):gst_dvdemux_convert_sink_pair: starting conversion of stop DEBUG (0x631fa0 - 0:00:04.101681000) dvdemux( 7118) gstdvdemux.c(446):gst_dvdemux_sink_convert:<dvdemux0> 2 -> 3 INFO (0x631fa0 - 0:00:04.101697000) dvdemux( 7118) gstdvdemux.c(448):gst_dvdemux_sink_convert:<dvdemux0> src_value:-1, src_format:2, dest_format:3 INFO (0x631fa0 - 0:00:04.101714000) dvdemux( 7118) gstdvdemux.c(832):gst_dvdemux_convert_sink_pair: Finished conversion of stop: -1 INFO (0x631fa0 - 0:00:04.101731000) dvdemux( 7118) gstdvdemux.c(344):gst_dvdemux_src_convert:<dvdemux0:video> src_value:0, src_format:3, dest_format:1 INFO (0x631fa0 - 0:00:04.101748000) dvdemux( 7118) gstdvdemux.c(429):gst_dvdemux_src_convert:<dvdemux0:video> Result : dest_format:1, dest_value:0, res:1 DEBUG (0x631fa0 - 0:00:04.101766000) dvdemux( 7118) gstdvdemux.c(1363):gst_dvdemux_demux_frame:<dvdemux0> sending segment start: 0:00:00.000000000, stop: 99:99:99.999999999, time: 0:00:00.000000000 DEBUG (0x631fa0 - 0:00:04.101873000) dvdemux( 7118) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 0:00:00.000000000 DEBUG (0x631fa0 - 0:00:04.101908000) dvdemux( 7118) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 0:00:00.000000000 chain ******* < (144000 bytes, timestamp: 0:00:00.000000000, duration: 0:00:00.040000000, offset: 0, offset_end: 1, flags: 0) 0x63d130 DEBUG (0x631fa0 - 0:00:04.140799000) dvdemux( 7118) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 0:00:00.040000000 DEBUG (0x631fa0 - 0:00:04.140850000) dvdemux( 7118) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 0:00:00.040000000 chain ******* < (144000 bytes, timestamp: 0:00:00.040000000, duration: 0:00:00.040000000, offset: 1, offset_end: 2, flags: 0) 0x63d2b0 DEBUG (0x631fa0 - 0:00:04.181543000) dvdemux( 7118) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 0:00:00.080000000 DEBUG (0x631fa0 - 0:00:04.181591000) dvdemux( 7118) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 0:00:00.080000000 chain ******* < (144000 bytes, timestamp: 0:00:00.080000000, duration: 0:00:00.040000000, offset: 2, offset_end: 3, flags: 0) 0x63d430 DEBUG (0x631fa0 - 0:00:04.221018000) dvdemux( 7118) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 0:00:00.120000000 DEBUG (0x631fa0 - 0:00:04.221065000) dvdemux( 7118) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 0:00:00.120000000 chain ******* < (144000 bytes, timestamp: 0:00:00.120000000, duration: 0:00:00.040000000, offset: 3, offset_end: 4, flags: 0) 0x63d5b0 DEBUG (0x631fa0 - 0:00:04.261802000) dvdemux( 7118) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 0:00:00.160000000 DEBUG (0x631fa0 - 0:00:04.261850000) dvdemux( 7118) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 0:00:00.160000000 chain ******* < (144000 bytes, timestamp: 0:00:00.160000000, duration: 0:00:00.040000000, offset: 4, offset_end: 5, flags: 0) 0x63d4b0 ... Note that each buffer received by fakesink has a duration of 0.04 seconds, and a monotonically increasing timestamp. When we add the rtpdemux element (which doesn't seem to forward NEWSEGMENT events), we get the following pipeline: gst-launch --gst-debug=dvdemux:5 udpsrc port=8000 ! queue ! rtpdemux ! rtpdvdepay queue-delay=0 ! dvdemux ! fakesink Setting pipeline to PAUSED ... Pipeline is live and does not need PREROLL ... Setting pipeline to PLAYING ... New clock: GstSystemClock DEBUG (0x639fc0 - 0:00:02.746882000) dvdemux( 7157) gstdvdemux.c(718):gst_dvdemux_handle_sink_event: NEWSEGMENT received DEBUG (0x639fc0 - 0:00:02.747391000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.747438000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.406051616, offset: 0, offset_end: 1, flags: 0) 0x641120 DEBUG (0x639fc0 - 0:00:02.786584000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.786632000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.446051616, offset: 1, offset_end: 2, flags: 0) 0x6412a0 DEBUG (0x639fc0 - 0:00:02.827162000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.827214000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.486051616, offset: 2, offset_end: 3, flags: 0) 0x641420 DEBUG (0x639fc0 - 0:00:02.866789000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.866837000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.526051616, offset: 3, offset_end: 4, flags: 0) 0x6415a0 DEBUG (0x639fc0 - 0:00:02.907381000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.907424000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.566051616, offset: 4, offset_end: 5, flags: 0) 0x6414a0 DEBUG (0x639fc0 - 0:00:02.946920000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.946964000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.606051616, offset: 5, offset_end: 6, flags: 0) 0x641320 DEBUG (0x639fc0 - 0:00:02.986617000) dvdemux( 7157) gstdvdemux.c(1234):gst_dvdemux_demux_audio: pushing audio 103:44:20.343500000 DEBUG (0x639fc0 - 0:00:02.986668000) dvdemux( 7157) gstdvdemux.c(1317):gst_dvdemux_demux_video: pushing video 103:44:20.343500000 chain ******* < (144000 bytes, timestamp: 103:44:20.343500000, duration: 5123991:50:13.646051616, offset: 6, offset_end: 7, flags: 0) 0x6411a0 Note how each buffer received by fakesink has the same timestamp as the previous buffer, but the duration (which is obviously wrong anyway) is increasing. I've looked through the source briefly. It seems that GstDVDemux->need_segment is initialized to FALSE, and set to TRUE on receiving a NEWSEGMENT event. Apparantly, timestamp administration is initialized properly when need_segment is TRUE, so when need_segment never is TRUE because of a lack of a NEWSEGMENT event, the timestamping goes wacko. If dvdemux cannot operate without receiving a NEWSEGMENT event, it should throw an error, rather than failing silently as it does now.
Oh, additionally, when dvdemux receives a NEWSEGMENT event with format GST_FORMAT_TIME, but no NEWSEGMENT event with format GST_FORMAT_BYTES, the same problem occurs, because GstDVDemux->need_segment is only set when a GST_FORMAT_BYTES NEWSEGMENT is received.
Hrm, this one's quite old. There *must* always be a newsegment event before any buffers (when operating push-based), so any situation where this is not the case is a bug elsewhere. It looks to me like dvdemux has code that handles both incoming newsegment events in BYTES and TIME format. need_segment only needs to be set when it received a BYTES newsegment from upstream, because that will tell it to generate a proper TIME newsegment event instead. This is not needed when upstream sends a TIME newsegment already, in which case the upstream one is just passed on. Anyway, I haven't actually done any tests, but the code looks in order at first glance, so I tihnk I'll just close this as OBSOLETE. If it's still an issue, I'm sure someone else will file a new bug sooner or later. Please re-open if you still have problems with up-to-date versions of GStreamer.