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 349436 - dvdemux outputs erroneous timestamp/duration when not receiving NEWSEGMENT event
dvdemux outputs erroneous timestamp/duration when not receiving NEWSEGMENT event
Status: RESOLVED OBSOLETE
Product: GStreamer
Classification: Platform
Component: gst-plugins-good
0.10.x
Other Linux
: Normal normal
: NONE
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2006-07-31 14:18 UTC by Marcel Moreaux
Modified: 2009-06-15 22:06 UTC
See Also:
GNOME target: ---
GNOME version: 2.13/2.14



Description Marcel Moreaux 2006-07-31 14:18:52 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.
Comment 1 Marcel Moreaux 2006-07-31 16:09:03 UTC
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.
Comment 2 Tim-Philipp Müller 2009-06-15 22:06:31 UTC
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.