Seek failed for hls stream

Tue Jun 28 15:00:13 UTC 2016

Hey all, 

I'm able to play an encrypted hls stream on Android, but when do the seek
action, it always failed. The reason is that it cannot fetch the key to
decrypt the stream. Here is related logs:

/06-28 15:54:02.226 D/Activity: onStopTrackingTouch: 0
06-28 15:54:02.226 D/GStreamer+tsdemux: 0:00:12.957620671 0xb3a65100
tsdemux.c:902:gst_ts_demux_srcpad_event:<src:audio_0101> Got event seek
06-28 15:54:02.226 I/GStreamer+adaptivedemux: 0:00:12.958387671 0xb3a65100
gstadaptivedemux.c:1245:gst_adaptive_demux_src_event:<hlsdemux0> Received
seek event
06-28 15:54:02.231 D/GStreamer+adaptivedemux: 0:00:12.959568171 0xb3a65100
gstadaptivedemux.c:1287:gst_adaptive_demux_src_event:<hlsdemux0> seek event,
seek event: 0xa97da648, time 99:99:99.999999999, seq-num 669, GstEventSeek,
rate=(double)1, format=(GstFormat)GST_FORMAT_TIME,
flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_KEY_UNIT,
cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0,
stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)0;
06-28 15:54:02.231 D/GStreamer+adaptivedemux: 0:00:12.960370838 0xb3a65100
gstadaptivedemux.c:1295:gst_adaptive_demux_src_event:<hlsdemux0> sending
flush start
06-28 15:54:02.231 I/GStreamer: GStreamer message: State changed to PAUSED
06-28 15:54:02.236 D/GStreamer+tsdemux: 0:00:12.967487005 0x9e341ec0
tsdemux.c:2663:gst_ts_demux_push_pending_data:<src:audio_0101> Returned
flushing
06-28 15:54:02.236 D/GStreamer+tsdemux: 0:00:12.967965171 0x9e341ec0
tsdemux.c:2665:gst_ts_demux_push_pending_data:<src:audio_0101> combined
flushing
06-28 15:54:02.236 V/GStreamer+tsdemux: 0:00:12.968351838 0x9e341ec0
tsdemux.c:2688:gst_ts_demux_push_pending_data Resetting to EMPTY, returning
flushing
06-28 15:54:02.236 D/GStreamer+adaptivedemux: 0:00:12.968979755 0x9e341ec0
gstadaptivedemux.c:2126:gst_adaptive_demux_stream_fragment_download_finish:<hlsdemux0:src_0>
Download finish: -2 flushing - err: 0x0
06-28 15:54:02.241 D/GStreamer+adaptivedemux: 0:00:12.969723671 0x9bfd86f0
gstadaptivedemux.c:2621:gst_adaptive_demux_stream_download_fragment:<hlsdemux0:src_0>
Fragment download result: -2 flushing
06-28 15:54:02.241 D/GStreamer+adaptivedemux: 0:00:12.970463505 0x9bfd86f0
gstadaptivedemux.c:2984:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
Stream has been cancelled
06-28 15:54:02.241 V/GStreamer+adaptivedemux: 0:00:12.970872338 0x9bfd86f0
gstadaptivedemux.c:2979:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
download loop end
06-28 15:54:02.241 D/GStreamer+adaptivedemux: 0:00:12.973795171 0xb3a65100
gstadaptivedemux.c:1376:gst_adaptive_demux_src_event:<hlsdemux0> Calling
subclass seek: seek event: 0xa97da648, time 99:99:99.999999999, seq-num 669,
GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME,
flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_KEY_UNIT,
cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0,
stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)0;
06-28 15:54:02.246 D/GStreamer+hlsdemux: 0:00:12.974464463 0xb3a65100
gsthlsdemux.c:346:gst_hls_demux_seek:<hlsdemux0> seeking to sequence 0
06-28 15:54:02.246 D/GStreamer+adaptivedemux: 0:00:12.975177005 0xb3a65100
gstadaptivedemux.c:1391:gst_adaptive_demux_src_event:<hlsdemux0> Sending
flush stop on all pad
06-28 15:54:02.251 D/GStreamer+tsdemux: 0:00:12.980421921 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb38180
06-28 15:54:02.251 D/GStreamer+tsdemux: 0:00:12.981139880 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb380c0
06-28 15:54:02.251 D/GStreamer+tsdemux: 0:00:12.982007963 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb38240
06-28 15:54:02.251 I/GStreamer+adaptivedemux: 0:00:12.982854713 0xb3a65100
gstadaptivedemux.c:1591:gst_adaptive_demux_start_tasks:<hlsdemux0> Starting
streams' tasks
06-28 15:54:02.251 V/GStreamer+adaptivedemux: 0:00:12.983620880 0x9bfd86f0
gstadaptivedemux.c:2675:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
download loop start
06-28 15:54:02.251 D/GStreamer+hls: 0:00:12.983754421 0x9bfd86f0
m3u8.c:890:gst_m3u8_client_get_next_fragment Looking for fragment 0
06-28 15:54:02.251 D/GStreamer+hls: 0:00:12.983853130 0x9bfd86f0
m3u8.c:907:gst_m3u8_client_get_next_fragment Got fragment with sequence 0
(client sequence 0)
06-28 15:54:02.251 D/GStreamer+adaptivedemux: 0:00:12.983968463 0x9bfd86f0
gstadaptivedemux.c:2805:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
Fragment info update result: 0 ok
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.984095130 0x9bfd86f0
gstadaptivedemux.c:2615:gst_adaptive_demux_stream_download_fragment:<hlsdemux0:src_0>
Got url 'http://stream_location' for stream 0x989291c0
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.984368463 0x9bfd86f0
gstadaptivedemux.c:2436:gst_adaptive_demux_stream_download_uri:<hlsdemux0:src_0>
Downloading uri: http://stream_location, range:0 - -1
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.984498921 0x9bfd86f0
gstadaptivedemux.c:2279:gst_adaptive_demux_stream_update_source:<hlsdemux0>
Re-using old source element
06-28 15:54:02.256 D/GStreamer+tsdemux: 0:00:12.984846880 0xb3a65100
tsdemux.c:902:gst_ts_demux_srcpad_event:<src:video_0100> Got event seek
06-28 15:54:02.256 I/GStreamer+adaptivedemux: 0:00:12.984986046 0xb3a65100
gstadaptivedemux.c:1245:gst_adaptive_demux_src_event:<hlsdemux0> Received
seek event
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.985265546 0xb3a65100
gstadaptivedemux.c:1287:gst_adaptive_demux_src_event:<hlsdemux0> seek event,
seek event: 0xa97da648, time 99:99:99.999999999, seq-num 669, GstEventSeek,
rate=(double)1, format=(GstFormat)GST_FORMAT_TIME,
flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_KEY_UNIT,
cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0,
stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)0;
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.985712255 0xb3a65100
gstadaptivedemux.c:1295:gst_adaptive_demux_src_event:<hlsdemux0> sending
flush start
06-28 15:54:02.256 D/GStreamer+uridownloader: 0:00:12.987759380 0xb3a65100
gsturidownloader.c:326:gst_uri_downloader_cancel:<uridownloader0> Trying to
cancel a download that was alredy cancelled
06-28 15:54:02.256 D/GStreamer+adaptivedemux: 0:00:12.988993546 0x9bfd86f0
gstadaptivedemux.c:2488:gst_adaptive_demux_stream_download_uri:<hlsdemux0:src_0>
Waiting for fragment download to finish: http://stream_location
06-28 15:54:02.261 D/GStreamer+adaptivedemux: 0:00:12.989205005 0x9bfd86f0
gstadaptivedemux.c:2621:gst_adaptive_demux_stream_download_fragment:<hlsdemux0:src_0>
Fragment download result: -2 flushing
06-28 15:54:02.261 D/GStreamer+adaptivedemux: 0:00:12.989321338 0x9bfd86f0
gstadaptivedemux.c:2984:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
Stream has been cancelled
06-28 15:54:02.261 V/GStreamer+adaptivedemux: 0:00:12.989427963 0x9bfd86f0
gstadaptivedemux.c:2979:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
download loop end
06-28 15:54:02.261 I/GStreamer: GStreamer current position: 0
06-28 15:54:02.261 I/GStreamer: GStreamer current duration: 119941
06-28 15:54:02.261 D/GStreamer+adaptivedemux: 0:00:12.994038963 0xb3a65100
gstadaptivedemux.c:1376:gst_adaptive_demux_src_event:<hlsdemux0> Calling
subclass seek: seek event: 0xa97da648, time 99:99:99.999999999, seq-num 669,
GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME,
flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_KEY_UNIT,
cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0,
stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)0;
06-28 15:54:02.266 D/GStreamer+hlsdemux: 0:00:12.994285505 0xb3a65100
gsthlsdemux.c:346:gst_hls_demux_seek:<hlsdemux0> seeking to sequence 0
06-28 15:54:02.266 D/GStreamer+adaptivedemux: 0:00:12.994394171 0xb3a65100
gstadaptivedemux.c:1391:gst_adaptive_demux_src_event:<hlsdemux0> Sending
flush stop on all pad
06-28 15:54:02.266 D/GStreamer+tsdemux: 0:00:12.997810963 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb38180
06-28 15:54:02.266 D/GStreamer+tsdemux: 0:00:12.997927588 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb380c0
06-28 15:54:02.266 D/GStreamer+tsdemux: 0:00:12.998173463 0xb3a65100
tsdemux.c:1718:gst_ts_demux_stream_flush flushing stream 0xaeb38240
06-28 15:54:02.266 I/GStreamer+adaptivedemux: 0:00:12.998339463 0xb3a65100
gstadaptivedemux.c:1591:gst_adaptive_demux_start_tasks:<hlsdemux0> Starting
streams' tasks
06-28 15:54:02.266 V/GStreamer+adaptivedemux: 0:00:12.998582046 0x9bfd86f0
gstadaptivedemux.c:2675:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
download loop start
06-28 15:54:02.266 D/GStreamer+hls: 0:00:12.998747796 0x9bfd86f0
m3u8.c:890:gst_m3u8_client_get_next_fragment Looking for fragment 0
06-28 15:54:02.266 D/GStreamer+hls: 0:00:12.998845296 0x9bfd86f0
m3u8.c:907:gst_m3u8_client_get_next_fragment Got fragment with sequence 0
(client sequence 0)
06-28 15:54:02.266 D/GStreamer+adaptivedemux: 0:00:12.998960296 0x9bfd86f0
gstadaptivedemux.c:2805:gst_adaptive_demux_stream_download_loop:<hlsdemux0:src_0>
Fragment info update result: 0 ok
06-28 15:54:02.271 D/GStreamer+adaptivedemux: 0:00:12.999079630 0x9bfd86f0
gstadaptivedemux.c:2615:gst_adaptive_demux_stream_download_fragment:<hlsdemux0:src_0>
Got url 'http://stream_location' for stream 0x989291c0
06-28 15:54:02.271 D/GStreamer+adaptivedemux: 0:00:12.999269713 0x9bfd86f0
gstadaptivedemux.c:2436:gst_adaptive_demux_stream_download_uri:<hlsdemux0:src_0>
Downloading uri: http://stream_location, range:0 - -1
06-28 15:54:02.271 D/GStreamer+adaptivedemux: 0:00:12.999392255 0x9bfd86f0
gstadaptivedemux.c:2279:gst_adaptive_demux_stream_update_source:<hlsdemux0>
Re-using old source element
06-28 15:54:02.271 D/GStreamer+adaptivedemux: 0:00:13.002301880 0x9bfd86f0
gstadaptivedemux.c:2488:gst_adaptive_demux_stream_download_uri:<hlsdemux0:src_0>
Waiting for fragment download to finish: http://stream_location
06-28 15:54:02.316 I/GStreamer+hlsdemux: 0:00:13.047171173 0x9e341ec0
gsthlsdemux.c:492:gst_hls_demux_start_fragment:<hlsdemux0> Fetching key
https://key_location
06-28 15:54:02.316 D/GStreamer+uridownloader: 0:00:13.047955131 0x9e341ec0
gsturidownloader.c:489:gst_uri_downloader_fetch_uri_with_range:<uridownloader0>
Fetching URI https://key_location
06-28 15:54:02.316 D/GStreamer+uridownloader: 0:00:13.048697798 0x9e341ec0
gsturidownloader.c:497:gst_uri_downloader_fetch_uri_with_range:<uridownloader0>
Cancelled, aborting fetch
06-28 15:54:02.321 D/GStreamer+uridownloader: 0:00:13.049307507 0x9e341ec0
gsturidownloader.c:597:gst_uri_downloader_fetch_uri_with_range:<uridownloader0>
Stopping source element souphttpsrc3
06-28 15:54:02.321 W/GStreamer+hlsdemux: 0:00:13.051727256 0x9e341ec0
gsthlsdemux.c:520:gst_hls_demux_start_fragment:<hlsdemux0> error: Couldn't
retrieve key for decryption
06-28 15:54:02.321 W/GStreamer+hlsdemux: 0:00:13.052573173 0x9e341ec0
gsthlsdemux.c:521:gst_hls_demux_start_fragment:<hlsdemux0> Failed to decrypt
data
06-28 15:54:02.321 I/GStreamer: GStreamer message: Error received from
element hlsdemux0: Couldn't retrieve key for decryption
06-28 15:54:02.326 W/GStreamer+basesrc: 0:00:13.057906423 0xad468830
gstbasesrc.c:2948:gst_base_src_loop:<souphttpsrc2> error: Internal data flow
error.
06-28 15:54:02.326 W/GStreamer+basesrc: 0:00:13.058449590 0xad468830
gstbasesrc.c:2948:gst_base_src_loop:<souphttpsrc2> error: streaming task
paused, reason error (-5)
06-28 15:54:02.331 W/GStreamer+adaptivedemux: 0:00:13.059100256 0xad468830
gstadaptivedemux.c:752:gst_adaptive_demux_handle_message:<hlsdemux0:src_0>
Source posted error: 4890:1 Internal data flow error. (gstbasesrc.c(2948):
gst_base_src_loop ():
/GstPipeline:pipeline0/GstHLSDemux:hlsdemux0/GstBin:srcbin-src_0/GstSoupHTTPSrc:souphttpsrc2:
                                              streaming task paused, reason
error (-5))/

After checking the source code on Github, from my view, it dosen't send the
request to the key_location to fetch the key, instead, it is blocked by
uridownloader->priv-cancelled == TRUE.

There is one position to turn it TRUE: in the function
gst_adaptive_demux_handle_seek_event in GstAdaptiveDemux.c, it calls the
function gst_adaptive_demux_stop_tasks under some conditions. But I'm not
sure what those conditions represent for and where those parameters come
from.

And there is one position to turn it FALSE: function
gst_uri_downloader_reset in GstUriDowloader.c, it is called in
gst_hls_demux_seek in GstHlsDemux.c under some conditions. As the same, I'm
not sure about the conditions.

I don't know if my analysis is in a right orientation, but even if right,
I'm still blocked by the things mentioned. I'm sorry that I cannot provide
any test because all the tests are in a closed network and the environment
is complecated. I hope someone could give me some ideas or suggestion, I
will appreciate very much :D

--
View this message in context: http://gstreamer-devel.966125.n4.nabble.com/Seek-failed-for-hls-stream-tp4678290.html
Sent from the GStreamer-devel mailing list archive at Nabble.com.