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 763165 - qtdemux: Seeking in push mode broken
qtdemux: Seeking in push mode broken
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins-good
1.7.90
Other Linux
: Normal blocker
: 1.7.91
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2016-03-06 08:08 UTC by Gregoire
Modified: 2016-05-31 14:27 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
log with *:4,qtdemux:6 (262.87 KB, application/zip)
2016-03-06 17:36 UTC, Gregoire
  Details
qtdemux: reset pending segment if we are already pushing one (1.78 KB, patch)
2016-03-07 13:45 UTC, Thiago Sousa Santos
committed Details | Review

Description Gregoire 2016-03-06 08:08:45 UTC
On Android 6.0.1 with gstreamer 1.7.90, a seek event such as:

gst_element_seek_simple(data->pipeline, GST_FORMAT_TIME, GST_SEEK_FLAG_FLUSH | GST_SEEK_FLAG_KEY_UNIT, s * GST_MSECOND);

works with the following pipeline:

playbin uri=file://path

while it's not working with the following pipeline:

filesrc location=path ! queue ! decodebin ! queue ! glimagesink

everything else not changed.



With the playbin pipeline, it's working as expected and the jump is immediate. After the seek event occurs, the video continues playing immediately at the new position. Here is the *:4 log. At 23:45:50.073, a seek to 31s is requested and at 23:45:50.174, the video plays at the 31s mark.


With the decodebin pipeline, after the seek event occurs at 23:30:17.396, there is an immediate jump for one frame, meaning that a frame of the 31s mark is displayed at 23:30:17.476. Nevertheless, the pipeline restarts from the beginning without displaying anything (the 31s frame is still visible) and once 31 seconds have elapsed at 23:30:49.176, the video resumes playing after the 31s mark.
Comment 1 Gregoire 2016-03-06 08:09:14 UTC
*:4 log for the playbin pipeline:

03-05 23:30:17.266  9153  9343 I GStreamer+baseparse: 0:01:56.302248081 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.287  9153  9343 I GStreamer+baseparse: 0:01:56.322558289 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.308  9153  9343 I GStreamer+baseparse: 0:01:56.343660216 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.325  9153  9343 I GStreamer+baseparse: 0:01:56.361348341 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.346  9153  9343 I GStreamer+baseparse: 0:01:56.382461726 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.364  9153  9343 I GStreamer+baseparse: 0:01:56.399867768 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.375  9153  9338 W GStreamer+amcvideodec: 0:01:56.411472508 0xdcc1e750 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xd1e19930 could not wait for frame, took too long
03-05 23:30:17.383  9153  9343 I GStreamer+baseparse: 0:01:56.418768862 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.396  9153  9153 D GStreamer+aiTennis3D: 0:01:56.431550320 0xf0d3fc00 gstreamer/aigstreamer.c:862:gst_native_seek Doing seek at 31713 mseconds
03-05 23:30:17.396  9153  9153 I GStreamer+GST_EVENT: 0:01:56.431771778 0xf0d3fc00 gstevent.c:1139:gst_event_new_seek creating seek rate 1.000000, format TIME, flags 5, start_type 1, start 0:00:31.713000000, stop_type 0, stop 0:00:00.000000000
03-05 23:30:17.403  9153  9153 I GStreamer+qtdemux: 0:01:56.439059122 0xf0d3fc00 qtdemux.c:1679:gst_qtdemux_handle_src_event:<qtdemux1> Time taken to parse index 0:00:00.007018594
03-05 23:30:17.403  9153  9153 I GStreamer+default: 0:01:56.439247924 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: bytes segment start=31713000000, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=31713000000, base=0, position 31713000000, duration -1
03-05 23:30:17.403  9153  9153 I GStreamer+GST_EVENT: 0:01:56.439365528 0xf0d3fc00 gstevent.c:1146:gst_event_new_seek creating seek rate 1.000000, format bytes, flags 5, start_type 1, start 236561809, stop_type 0, stop -1
03-05 23:30:17.404  9153  9153 I GStreamer+GST_STATES: 0:01:56.439593705 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:30:17.404  9153  9153 I GStreamer+GST_STATES: 0:01:56.439837820 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:30:17.404  9153  9153 I GStreamer+GST_STATES: 0:01:56.440046310 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:30:17.404  9153  9336 I System.out: Gst setMessage (0) State changed (0) to PAUSED
03-05 23:30:17.405  9153  9338 W GStreamer+amcvideodec: 0:01:56.440708185 0xdcc1e750 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xd1e19a50 could not wait for frame, took too long
03-05 23:30:17.409  9153  9349 I GStreamer+task: 0:01:56.444843966 0xce839ac0 gsttask.c:316:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task going to paused
03-05 23:30:17.409  9153  9343 E GStreamer+amcvideodec: 0:01:56.444864383 0xce9bdf50 gstamcvideodec.c:2257:gst_amc_video_dec_handle_frame:<amcvideodec-omxqcomvideodecoderavc1> Downstream returned flushing
03-05 23:30:17.409  9153  9343 I GStreamer+task: 0:01:56.445465685 0xce9bdf50 gsttask.c:316:gst_task_func:<multiqueue1:src_0> Task going to paused
03-05 23:30:17.410  9153  9263 I GStreamer+task: 0:01:56.446283341 0xdd68ed80 gsttask.c:316:gst_task_func:<queue3:src> Task going to paused
03-05 23:30:17.410  9153  9341 I GStreamer+task: 0:01:56.446366414 0xdd68eef0 gsttask.c:316:gst_task_func:<queue2:src> Task going to paused
03-05 23:30:17.410  9153  9342 I GStreamer+basesrc: 0:01:56.446452195 0xdd68ef20 gstbasesrc.c:2856:gst_base_src_loop:<filesrc1> pausing after gst_pad_push() = flushing
03-05 23:30:17.411  9153  9153 I GStreamer+default: 0:01:56.446660424 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955
03-05 23:30:17.411  9153  9153 I GStreamer+basesrc: 0:01:56.446806466 0xf0d3fc00 gstbasesrc.c:1344:gst_base_src_do_seek:<filesrc1> seeking: bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955
03-05 23:30:17.411  9153  9153 I GStreamer+GST_EVENT: 0:01:56.446888341 0xf0d3fc00 gstevent.c:547:gst_event_new_flush_stop creating flush stop 1
03-05 23:30:17.411  9153  9153 I GStreamer+GST_EVENT: 0:01:56.447058393 0xf0d3fc00 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
03-05 23:30:17.411  9153  9342 I GStreamer+task: 0:01:56.447103758 0xdd68ef20 gsttask.c:316:gst_task_func:<filesrc1:src> Task going to paused
03-05 23:30:17.414  9153  9341 I GStreamer+task: 0:01:56.450051258 0xdd68eef0 gsttask.c:318:gst_task_func:<queue2:src> Task resume from paused
03-05 23:30:17.414  9153  9349 I GStreamer+task: 0:01:56.450099278 0xce839ac0 gsttask.c:318:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task resume from paused
03-05 23:30:17.414  9153  9263 I GStreamer+task: 0:01:56.450172455 0xdd68ed80 gsttask.c:318:gst_task_func:<queue3:src> Task resume from paused
03-05 23:30:17.414  9153  9342 I GStreamer+task: 0:01:56.450124747 0xdd68ef20 gsttask.c:318:gst_task_func:<filesrc1:src> Task resume from paused
03-05 23:30:17.414  9153  9343 I GStreamer+task: 0:01:56.450280580 0xce9bdf50 gsttask.c:318:gst_task_func:<multiqueue1:src_0> Task resume from paused
03-05 23:30:17.416  9153  9342 I GStreamer+GST_EVENT: 0:01:56.451836830 0xdd68ef20 gstevent.c:760:gst_event_new_segment creating segment event bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955
03-05 23:30:17.416  9153  9342 I GStreamer+basesrc: 0:01:56.452032403 0xdd68ef20 gstbasesrc.c:2843:gst_base_src_loop:<filesrc1> marking pending DISCONT
03-05 23:30:17.416  9153  9341 I GStreamer+GST_EVENT: 0:01:56.452191778 0xdd68eef0 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 0:00:41.982000000
03-05 23:30:17.431  9153  9343 I GStreamer+h264parse: 0:01:56.467239018 0xce9bdf50 gsth264parse.c:743:gst_h264_parse_process_nal:<h264parse1> have SPS/PPS in stream
03-05 23:30:17.432  9153  9343 I GStreamer+baseparse: 0:01:56.467729122 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.444  9153  9343 I GStreamer+baseparse: 0:01:56.480119018 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.446  9153  9343 I GStreamer+baseparse: 0:01:56.482092091 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.455  9153  9343 I GStreamer+baseparse: 0:01:56.491021622 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.460  9153  9343 I GStreamer+baseparse: 0:01:56.496388185 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.462  9153  9343 I GStreamer+baseparse: 0:01:56.498106205 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.467  9153  9263 I GStreamer+GST_STATES: 0:01:56.502979278 0xdd68ed80 gstbin.c:3238:bin_handle_async_done:<glimagesinkbin1> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:30:17.467  9153  9263 I GStreamer+GST_STATES: 0:01:56.503159539 0xdd68ed80 gstbin.c:3258:bin_handle_async_done:<glimagesinkbin1> completed state change, pending VOID
03-05 23:30:17.467  9153  9263 I GStreamer+GST_STATES: 0:01:56.503283080 0xdd68ed80 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending)
03-05 23:30:17.467  9153  9343 I GStreamer+baseparse: 0:01:56.503355737 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.467  9153  9263 I GStreamer+GST_STATES: 0:01:56.503423393 0xdd68ed80 gstbin.c:3238:bin_handle_async_done:<pipeline1> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:30:17.468  9153  9263 I GStreamer+GST_STATES: 0:01:56.503506466 0xdd68ed80 gstbin.c:3267:bin_handle_async_done:<pipeline1> continue state change, pending PLAYING
03-05 23:30:17.468  9153  9263 I GStreamer+GST_STATES: 0:01:56.503595893 0xdd68ed80 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PAUSED (PLAYING pending)
03-05 23:30:17.468  9153  9350 I GStreamer+GST_STATES: 0:01:56.503794591 0xdcfa3630 gstbin.c:3061:gst_bin_continue_func:<pipeline1> continue state change PAUSED to PLAYING, final PLAYING
03-05 23:30:17.468  9153  9336 I System.out: Gst setMessage (0) State changed (0) to PAUSED
03-05 23:30:17.468  9153  9350 I GStreamer+GST_EVENT: 0:01:56.504190528 0xdcfa3630 gstevent.c:1253:gst_event_new_latency creating latency event 0:00:00.000000000
03-05 23:30:17.468  9153  9350 I GStreamer+bin: 0:01:56.504405737 0xdcfa3630 gstbin.c:2593:gst_bin_do_latency_func:<pipeline1> configured latency of 0:00:00.000000000
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.504542612 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glimagesinkbin1> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.504664330 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.504771830 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<sink> completed state change to PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.504877716 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505005685 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'sink' changed state to 4(PLAYING) successfully
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505107143 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glcolorbalance1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505201518 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<glcolorbalance1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505286310 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorbalance1' changed state to 4(PLAYING) successfully
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505380945 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glcolorconvertelement1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.469  9153  9350 I GStreamer+GST_STATES: 0:01:56.505453185 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<glcolorconvertelement1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505527508 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorconvertelement1' changed state to 4(PLAYING) successfully
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505604174 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<gluploadelement1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505680997 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<gluploadelement1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505755424 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'gluploadelement1' changed state to 4(PLAYING) successfully
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505839122 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<glimagesinkbin1> completed state change to PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.505981362 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:30:17.470  9153  9343 I GStreamer+baseparse: 0:01:56.506020737 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.506208445 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'glimagesinkbin1' changed state to 4(PLAYING) successfully
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.506308966 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<identity0> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.506391622 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<identity0> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.470  9153  9350 I GStreamer+GST_STATES: 0:01:56.506465841 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'identity0' changed state to 4(PLAYING) successfully
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506549278 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<queue3> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506625112 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<queue3> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506691674 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'queue3' changed state to 4(PLAYING) successfully
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506772351 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<decodebin0> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506886310 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.506962039 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507037872 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'amcvideodec-omxqcomvideodecoderavc1' changed state to 4(PLAYING) successfully
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507139330 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<capsfilter1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507221258 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<capsfilter1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507314174 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'capsfilter1' changed state to 4(PLAYING) successfully
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507410580 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.471  9153  9343 I GStreamer+baseparse: 0:01:56.507449747 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:17.471  9153  9350 I GStreamer+GST_STATES: 0:01:56.507486883 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<h264parse1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507563758 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'h264parse1' changed state to 4(PLAYING) successfully
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507656830 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<multiqueue1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507742872 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<multiqueue1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507821674 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'multiqueue1' changed state to 4(PLAYING) successfully
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507915112 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<qtdemux1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.507993185 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<qtdemux1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508068914 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'qtdemux1' changed state to 4(PLAYING) successfully
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508150112 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<typefind> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508221622 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<typefind> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508294851 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'typefind' changed state to 4(PLAYING) successfully
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508373653 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<decodebin0> completed state change to PLAYING
03-05 23:30:17.472  9153  9350 I GStreamer+GST_STATES: 0:01:56.508450424 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'decodebin0' changed state to 4(PLAYING) successfully
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508532299 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<queue2> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508602820 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<queue2> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508676101 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'queue2' changed state to 4(PLAYING) successfully
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508752664 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<filesrc1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508827820 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<filesrc1> skipping transition from PLAYING to  PLAYING
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508898810 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'filesrc1' changed state to 4(PLAYING) successfully
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.508973810 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<pipeline1> completed state change to PLAYING
03-05 23:30:17.473  9153  9350 I GStreamer+GST_STATES: 0:01:56.509045268 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:30:17.473  9153  9336 I System.out: Gst setMessage (0) State changed (0) to PLAYING
03-05 23:30:17.476  9153  9343 I GStreamer+baseparse: 0:01:56.512364695 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.176  9153  9343 I GStreamer+baseparse: 0:02:28.212247964 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.207  9153  9343 I GStreamer+baseparse: 0:02:28.243114683 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.230  9153  9343 I GStreamer+baseparse: 0:02:28.265742131 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.245  9153  9343 I GStreamer+baseparse: 0:02:28.280961245 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.265  9153  9343 I GStreamer+baseparse: 0:02:28.300784266 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.288  9153  9343 I GStreamer+baseparse: 0:02:28.323874683 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:30:49.307  9153  9343 I GStreamer+baseparse: 0:02:28.342964006 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
Comment 2 Gregoire 2016-03-06 08:11:26 UTC
*:4 log for the playbin pipeline:

03-05 23:45:50.053 10004 10183 I GStreamer+baseparse: 0:01:43.665038554 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.055 10004 10183 I GStreamer+baseparse: 0:01:43.667027929 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.061 10004 10183 I GStreamer+baseparse: 0:01:43.673179075 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.068 10004 10183 I GStreamer+videodecoder: 0:01:43.680391940 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)59523670;
03-05 23:45:50.073 10004 10004 D GStreamer+aiTennis3D: 0:01:43.685840638 0xf0d3fc00 gstreamer/aigstreamer.c:862:gst_native_seek Doing seek at 31713 mseconds
03-05 23:45:50.073 10004 10004 I GStreamer+GST_EVENT: 0:01:43.686014232 0xf0d3fc00 gstevent.c:1139:gst_event_new_seek creating seek rate 1.000000, format TIME, flags 5, start_type 1, start 0:00:31.713000000, stop_type 0, stop 0:00:00.000000000
03-05 23:45:50.083 10004 10004 I GStreamer+qtdemux: 0:01:43.695640117 0xf0d3fc00 qtdemux.c:1679:gst_qtdemux_handle_src_event:<qtdemux1> Time taken to parse index 0:00:00.009257083
03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698018294 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698366054 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698651159 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:45:50.086 10004 10182 I GStreamer+task: 0:01:43.698954127 0xcfc47d50 gsttask.c:316:gst_task_func:<qtdemux1:sink> Task going to paused
03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.699005429 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:45:50.087 10004 10004 I GStreamer+GST_STATES: 0:01:43.699304075 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending)
03-05 23:45:50.087 10004 10183 I GStreamer+task: 0:01:43.699361992 0xd24d29b0 gsttask.c:316:gst_task_func:<multiqueue1:src_0> Task going to paused
03-05 23:45:50.087 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PAUSED
03-05 23:45:50.088 10004 10189 I GStreamer+task: 0:01:43.700083294 0xd24d2460 gsttask.c:316:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task going to paused
03-05 23:45:50.088 10004 10190 I GStreamer+task: 0:01:43.700375638 0xdcf6dbb0 gsttask.c:316:gst_task_func:<vqueue:src> Task going to paused
03-05 23:45:50.088 10004 10004 I GStreamer+default: 0:01:43.700722721 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 0:00:41.982000000
03-05 23:45:50.088 10004 10004 I GStreamer+GST_EVENT: 0:01:43.700878450 0xf0d3fc00 gstevent.c:547:gst_event_new_flush_stop creating flush stop 1
03-05 23:45:50.092 10004 10189 I GStreamer+task: 0:01:43.704026054 0xd24d2460 gsttask.c:318:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task resume from paused
03-05 23:45:50.092 10004 10190 I GStreamer+task: 0:01:43.704674857 0xdcf6dbb0 gsttask.c:318:gst_task_func:<vqueue:src> Task resume from paused
03-05 23:45:50.092 10004 10182 I GStreamer+task: 0:01:43.704727565 0xcfc47d50 gsttask.c:318:gst_task_func:<qtdemux1:sink> Task resume from paused
03-05 23:45:50.092 10004 10183 I GStreamer+task: 0:01:43.704789492 0xd24d29b0 gsttask.c:318:gst_task_func:<multiqueue1:src_0> Task resume from paused
03-05 23:45:50.092 10004 10182 I GStreamer+GST_EVENT: 0:01:43.704940221 0xcfc47d50 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 99:99:99.999999999
03-05 23:45:50.102 10004 10183 I GStreamer+h264parse: 0:01:43.714807565 0xd24d29b0 gsth264parse.c:743:gst_h264_parse_process_nal:<h264parse1> have SPS/PPS in stream
03-05 23:45:50.103 10004 10183 I GStreamer+baseparse: 0:01:43.715352200 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.125 10004 10183 I GStreamer+baseparse: 0:01:43.737678190 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.126 10004 10183 I GStreamer+videodecoder: 0:01:43.738612565 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60183201;
03-05 23:45:50.128 10004 10183 I GStreamer+baseparse: 0:01:43.740961211 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.130 10004 10183 I GStreamer+baseparse: 0:01:43.742697825 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.131 10004 10183 I GStreamer+videodecoder: 0:01:43.743435169 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60234534;
03-05 23:45:50.142 10004 10189 I GStreamer+GST_EVENT: 0:01:43.754383607 0xd24d2460 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 99:99:99.999999999
03-05 23:45:50.149 10004 10183 I GStreamer+baseparse: 0:01:43.761115377 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.150 10004 10183 I GStreamer+baseparse: 0:01:43.762864648 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.151 10004 10183 I GStreamer+videodecoder: 0:01:43.763510482 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60265334;
03-05 23:45:50.152 10004 10183 I GStreamer+baseparse: 0:01:43.764953450 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.153 10004 10183 I GStreamer+videodecoder: 0:01:43.765533034 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60323649;
03-05 23:45:50.154 10004 10183 I GStreamer+baseparse: 0:01:43.766562721 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.159 10004 10183 I GStreamer+baseparse: 0:01:43.771724232 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.159 10004 10190 I GStreamer+GST_STATES: 0:01:43.771971315 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<glimagesinkbin1> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772073034 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<glimagesinkbin1> completed state change, pending VOID
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772178919 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending)
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772343554 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<vbin> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772497200 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<vbin> completed state change, pending VOID
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772603346 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending)
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772751002 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<playsink> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772869857 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<playsink> completed state change, pending VOID
03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.773009284 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending)
03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773318450 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<playbin1> committing state from PAUSED to PAUSED, old pending PLAYING
03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773436679 0xdcf6dbb0 gstbin.c:3267:bin_handle_async_done:<playbin1> continue state change, pending PLAYING
03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773530325 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PAUSED (PLAYING pending)
03-05 23:45:50.161 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PAUSED
03-05 23:45:50.162 10004 10191 I GStreamer+GST_STATES: 0:01:43.774054804 0xdc9faf20 gstbin.c:3061:gst_bin_continue_func:<playbin1> continue state change PAUSED to PLAYING, final PLAYING
03-05 23:45:50.162 10004 10191 I GStreamer+GST_EVENT: 0:01:43.774669075 0xdc9faf20 gstevent.c:1253:gst_event_new_latency creating latency event 0:00:00.000000000
03-05 23:45:50.163 10004 10191 I GStreamer+bin: 0:01:43.775059961 0xdc9faf20 gstbin.c:2593:gst_bin_do_latency_func:<playbin1> configured latency of 0:00:00.000000000
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775209909 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<playsink> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775337982 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vbin> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775456002 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glimagesinkbin1> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.163 10004 10183 I GStreamer+baseparse: 0:01:43.775486992 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775577461 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775690377 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<sink> completed state change to PLAYING
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775788086 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775993554 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'sink' changed state to 4(PLAYING) successfully
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776097409 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glcolorbalance1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776185429 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<glcolorbalance1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776276054 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorbalance1' changed state to 4(PLAYING) successfully
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776376992 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glcolorconvertelement1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776463867 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<glcolorconvertelement1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776556054 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorconvertelement1' changed state to 4(PLAYING) successfully
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776658607 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<gluploadelement1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776748659 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<gluploadelement1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776839075 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'gluploadelement1' changed state to 4(PLAYING) successfully
03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776937200 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<glimagesinkbin1> completed state change to PLAYING
03-05 23:45:50.165 10004 10191 I GStreamer+GST_STATES: 0:01:43.777025429 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:45:50.165 10004 10191 I GStreamer+GST_STATES: 0:01:43.777971315 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'glimagesinkbin1' changed state to 4(PLAYING) successfully
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778173086 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vconv> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778331054 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<scale> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778422252 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<scale> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778524388 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'scale' changed state to 4(PLAYING) successfully
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778619284 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<conv> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778795690 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<conv> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778890221 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'conv' changed state to 4(PLAYING) successfully
03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778990013 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<identity> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779132982 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<identity> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779227200 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'identity' changed state to 4(PLAYING) successfully
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779326002 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vconv> completed state change to PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779417825 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'vconv' changed state to 4(PLAYING) successfully
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779519596 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vqueue> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779618815 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<vqueue> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779708398 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'vqueue' changed state to 4(PLAYING) successfully
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779811211 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vbin> completed state change to PLAYING
03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779909075 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780519179 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'vbin' changed state to 4(PLAYING) successfully
03-05 23:45:50.168 10004 10183 I GStreamer+baseparse: 0:01:43.780613659 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780725638 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vdbin> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780875482 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vdconv> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780963919 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<vdconv> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781058242 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vdbin> child 'vdconv' changed state to 4(PLAYING) successfully
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781157721 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vdbin> completed state change to PLAYING
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781251159 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'vdbin' changed state to 4(PLAYING) successfully
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781357825 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<streamsynchronizer1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781444857 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<streamsynchronizer1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781536575 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'streamsynchronizer1' changed state to 4(PLAYING) successfully
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781643346 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<playsink> completed state change to PLAYING
03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781748138 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782088607 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'playsink' changed state to 4(PLAYING) successfully
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782207252 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<inputselector1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782295742 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<inputselector1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782546627 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'inputselector1' changed state to 4(PLAYING) successfully
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782671940 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<uridecodebin1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782804700 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<decodebin1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782957304 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783051784 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783140117 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'amcvideodec-omxqcomvideodecoderavc1' changed state to 4(PLAYING) successfully
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783243763 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<capsfilter1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783331263 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<capsfilter1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783422044 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'capsfilter1' changed state to 4(PLAYING) successfully
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783527304 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783618971 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<h264parse1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783707929 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'h264parse1' changed state to 4(PLAYING) successfully
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783810898 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<multiqueue1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783903242 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<multiqueue1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783991471 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'multiqueue1' changed state to 4(PLAYING) successfully
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784093607 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<qtdemux1> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784178346 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<qtdemux1> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784266419 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'qtdemux1' changed state to 4(PLAYING) successfully
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784362617 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<typefind> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784448294 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<typefind> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784540794 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'typefind' changed state to 4(PLAYING) successfully
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784646732 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<decodebin1> completed state change to PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784760742 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<uridecodebin1> child 'decodebin1' changed state to 4(PLAYING) successfully
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784860898 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<source> current PLAYING pending VOID_PENDING, desired next PLAYING
03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784950846 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<source> skipping transition from PLAYING to  PLAYING
03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785049544 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<uridecodebin1> child 'source' changed state to 4(PLAYING) successfully
03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785152461 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<uridecodebin1> completed state change to PLAYING
03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785252096 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'uridecodebin1' changed state to 4(PLAYING) successfully
03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785346263 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<playbin1> completed state change to PLAYING
03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785442096 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
03-05 23:45:50.173 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PLAYING
03-05 23:45:50.174 10004 10183 I GStreamer+baseparse: 0:01:43.786688659 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.180 10004 10183 I GStreamer+baseparse: 0:01:43.792532148 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.187 10004 10183 I GStreamer+baseparse: 0:01:43.799091784 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.206 10004 10183 I GStreamer+baseparse: 0:01:43.818876159 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.245 10004 10183 I GStreamer+baseparse: 0:01:43.857767773 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.266 10004 10183 I GStreamer+baseparse: 0:01:43.878381940 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.286 10004 10183 I GStreamer+baseparse: 0:01:43.898369804 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.305 10004 10183 I GStreamer+baseparse: 0:01:43.917465013 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.323 10004 10183 I GStreamer+videodecoder: 0:01:43.935723659 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60381142;
03-05 23:45:50.345 10004 10183 I GStreamer+baseparse: 0:01:43.957159752 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.365 10004 10183 I GStreamer+baseparse: 0:01:43.977548971 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.383 10004 10183 I GStreamer+baseparse: 0:01:43.995340638 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.396 10004 10181 W GStreamer+amcvideodec: 0:01:44.008156158 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd059530 could not wait for frame, took too long
03-05 23:45:50.402 10004 10183 I GStreamer+baseparse: 0:01:44.014981211 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.421 10004 10183 I GStreamer+baseparse: 0:01:44.033639231 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.440 10004 10183 I GStreamer+baseparse: 0:01:44.052932044 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.460 10004 10183 I GStreamer+baseparse: 0:01:44.072131419 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.480 10004 10183 I GStreamer+baseparse: 0:01:44.092328190 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.499 10004 10183 I GStreamer+baseparse: 0:01:44.111938242 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.519 10004 10183 I GStreamer+baseparse: 0:01:44.131230586 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.537 10004 10183 I GStreamer+baseparse: 0:01:44.149844127 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.556 10004 10183 I GStreamer+videodecoder: 0:01:44.168187981 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60439868;
03-05 23:45:50.577 10004 10183 I GStreamer+baseparse: 0:01:44.189096783 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.602 10004 10183 I GStreamer+baseparse: 0:01:44.214494804 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.617 10004 10183 I GStreamer+baseparse: 0:01:44.229538919 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.632 10004 10181 W GStreamer+amcvideodec: 0:01:44.244060065 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd059530 could not wait for frame, took too long
03-05 23:45:50.650 10004 10183 I GStreamer+baseparse: 0:01:44.262792096 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.673 10004 10183 I GStreamer+baseparse: 0:01:44.285156835 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.674 10004 10183 I GStreamer+baseparse: 0:01:44.286759960 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.676 10004 10183 I GStreamer+baseparse: 0:01:44.288144231 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.677 10004 10183 I GStreamer+baseparse: 0:01:44.289375169 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.685 10004 10183 I GStreamer+baseparse: 0:01:44.297046992 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.694 10004 10183 I GStreamer+baseparse: 0:01:44.306973971 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.713 10004 10183 I GStreamer+baseparse: 0:01:44.325366471 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.731 10004 10183 I GStreamer+videodecoder: 0:01:44.343390846 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60499825;
03-05 23:45:50.772 10004 10183 I GStreamer+baseparse: 0:01:44.384426367 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.791 10004 10183 I GStreamer+baseparse: 0:01:44.403337981 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.793 10004 10183 I GStreamer+baseparse: 0:01:44.405854283 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.811 10004 10183 I GStreamer+baseparse: 0:01:44.423278710 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.851 10004 10183 I GStreamer+baseparse: 0:01:44.463315742 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.869 10004 10183 I GStreamer+baseparse: 0:01:44.481726002 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.879 10004 10181 W GStreamer+amcvideodec: 0:01:44.491802617 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd058ba0 could not wait for frame, took too long
03-05 23:45:50.888 10004 10183 I GStreamer+baseparse: 0:01:44.500531679 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
03-05 23:45:50.908 10004 10183 I GStreamer+baseparse: 0:01:44.520872669 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
Comment 3 Gregoire 2016-03-06 08:12:30 UTC
Comment #1 is the log of the decodebin pipeline. Sorry for the confusion. Comment #2 is the log of the playbin pipeline (no error here).
Comment 4 Sebastian Dröge (slomo) 2016-03-06 08:18:27 UTC
Does this happen on all files, or only MP4 files? Does it only happen if amcvideodec is used?

Can you provide a *:6 debug log for the failing case?
Comment 5 Gregoire 2016-03-06 08:47:17 UTC
It's working fine with:
https://download.blender.org/peach/bigbuckbunny_movies/big_buck_bunny_480p_stereo.ogg

So I tend to believe that it's an mp4 only problem
Comment 6 Sebastian Dröge (slomo) 2016-03-06 08:49:55 UTC
Try with a Matroska/MKV file that also contains H264. The Ogg file contains Theora, for which amcvideodec is not going to be used.
Comment 7 Gregoire 2016-03-06 09:04:08 UTC
I have "handbrake" the h264-mp4 file and I'm getting a h264 mkv file which is working fine. this mkv file reports h264-mpeg-4-avc in VLC so I guess that it's indeed a h264 video muxed in a mkv container.

I have some trouble to create a *:6 log file. Too much log. The video doesn't start,

Is there a relevant subset log to provide? What should I do now?
Comment 8 Sebastian Dröge (slomo) 2016-03-06 09:09:12 UTC
Just to make sure, does it fail on every MP4 file you try or a specific one?

Also please try without linking in the androidmedia plugin (i.e. using the libav plugin instead). After that I can probably tell you what other categories to use.
Comment 9 Gregoire 2016-03-06 09:10:44 UTC
short log seems to show that it's still amcvideodec that is used in case of this h264 mkv file. Definitely hardware decoder used in this case.

Therefore, the problem seems to be related to the mp4 container only when decodebin is used.
Comment 10 Gregoire 2016-03-06 09:15:41 UTC
It seems to do it for EVERY h264 mp4 file I have tried so far.
Comment 11 Gregoire 2016-03-06 09:22:14 UTC
It also seems that it's failing without androidmedia.
Comment 12 Sebastian Dröge (slomo) 2016-03-06 09:58:31 UTC
Ok, *:4,qtdemux:6 might help then.
Comment 13 Gregoire 2016-03-06 17:36:03 UTC
Created attachment 323200 [details]
log with *:4,qtdemux:6

The seek command occurs at 09:27:50.526 (26384-msecond mark) and the video resumes 26 seconds later at 09:28:17.713.
Comment 14 Sebastian Dröge (slomo) 2016-03-07 07:18:20 UTC
Not sure why your pipeline runs in push mode, but that is the problem. Seeking in push mode in qtdemux seems completely broken:

> gst-play-1.0 pushfile:///path/to/mp4/file

Trying to seek with the arrow keys starts from 0 again
Comment 15 Sebastian Dröge (slomo) 2016-03-07 07:24:15 UTC
git bisect shows this as the problematic commit:

2dbc9f86fce28f7f06205b6668d568e754b89ba9 is the first bad commit
commit 2dbc9f86fce28f7f06205b6668d568e754b89ba9
Author: Thiago Santos <thiagoss@osg.samsung.com>
Date:   Tue Nov 24 10:57:28 2015 -0300

    qtdemux: restore the segment on case of soft reset
    
    When seeking back to restore the mdat position a flush is pushed
    through and it resets downstream segment information. Make sure
    that after the flush (that does a soft reset) a segment will
    be pushed again
    
    Fixes regressions spotted at
    https://ci.gstreamer.net/job/GStreamer-master-validate/2100/
Comment 16 Gregoire 2016-03-07 08:03:30 UTC
Man, how do you do that??? :-) I know it's your project but how do you find a bisect in seconds?

What is push mode? And why don't I get all the good memos about critical changes and new features? ;-)

Anyway, reverting 2dbc9f86fce28f7f06205b6668d568e754b89ba9 fixes the problem on my Android system. I can now seek in both directions.
Comment 17 Sebastian Dröge (slomo) 2016-03-07 10:22:23 UTC
(In reply to Gregoire from comment #16)
> Man, how do you do that??? :-) I know it's your project but how do you find
> a bisect in seconds?

git bisect master..1.6.0 -- gst/isomp4
and then running through that step by step until it tells me the offending commit. Only knowledge needed here is that the problem is in gst-plugins-good/gst/isomp4 and that it worked in 1.6.0 :) And you need a testcase

> What is push mode? And why don't I get all the good memos about critical
> changes and new features? ;-)

This one is a bug, not really a critical change or new feature :) A bugfix for something else that caused a new bug.

Push mode is when the source (or upstream in general) gives you buffers one after another at its own pace (and block size). Pull mode is when downstream (the demuxer usually) asks upstream (the source usually) for buffers from a specific offset with a specific size.

> Anyway, reverting 2dbc9f86fce28f7f06205b6668d568e754b89ba9 fixes the problem
> on my Android system. I can now seek in both directions.

Thanks for confirming
Comment 18 Thiago Sousa Santos 2016-03-07 13:45:41 UTC
Created attachment 323275 [details] [review]
qtdemux: reset pending segment if we are already pushing one

When upstream is running in bytes in push-mode, qtdemux will
convert seeks from time to bytes and send it upstream. Upstream
element will perform a byte seek and send a byte segment to qtdemux
that will convert it to time and push it downstream.

There is, however, the pending_segment variable that stores a new
segment event to be pushed before the next data. When handling seeks
as mentioned above this variable was being ignored and, if it contained
some segment event, it would override the one resulting from the seek.
This would restore a previous segment and would cause the seek segment
to be discarded downstream.

This patch fixes this issue by unrefing any pending segment as the
seek from upstream should contain the latest one that should be
used, as requested by the application.
Comment 19 Gregoire 2016-03-07 18:29:26 UTC
I confirm that it's working with the new patch attachment 323275 [details] [review].

Thanks!!! It seems to work great now.
Comment 20 Thiago Sousa Santos 2016-03-07 18:31:53 UTC
commit d8fb7a9c96b108814beeaa0e63f818d4648c7fe9
Author: Thiago Santos <thiagoss@osg.samsung.com>
Date:   Mon Mar 7 10:28:06 2016 -0300

    qtdemux: reset pending segment if we are already pushing one
    
    When upstream is running in bytes in push-mode, qtdemux will
    convert seeks from time to bytes and send it upstream. Upstream
    element will perform a byte seek and send a byte segment to qtdemux
    that will convert it to time and push it downstream.
    
    There is, however, the pending_segment variable that stores a new
    segment event to be pushed before the next data. When handling seeks
    as mentioned above this variable was being ignored and, if it contained
    some segment event, it would override the one resulting from the seek.
    This would restore a previous segment and would cause the seek segment
    to be discarded downstream.
    
    This patch fixes this issue by unrefing any pending segment as the
    seek from upstream should contain the latest one that should be
    used, as requested by the application.
    
    https://bugzilla.gnome.org/show_bug.cgi?id=763165