Seek failed for hls stream

[Xinheng]

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

[Sebastian Dröge-3]

On Di, 2016-06-28 at 08:00 -0700, silver wrote:
> [...]
> 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

Please file a bug with this analysis :)

Also the best would be if you could try to create a patch for hlsdemux,
you seem to have an understanding of what is needed already and can
just try a few things to see if that works. Having a patch would make
it easier for us also to understand the problem and maybe propose a
cleaner solution... unless your patch is perfect already, which it
might very well be.

--
Sebastian Dröge, Centricular Ltd · http://www.centricular.com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Xinheng]

Well, perhaps that's not the problem of those conditions. I found in GstAdaptiveDemux.c, the function gst_adaptive_demux_start_tasks and gst_adaptive_demux_stop_tasks:

static void
gst_adaptive_demux_start_tasks (GstAdaptiveDemux * demux)
{
  GList *iter;

  GST_INFO_OBJECT (demux, "Starting streams' tasks");
  for (iter = demux->streams; iter; iter = g_list_next (iter)) {
    GstAdaptiveDemuxStream *stream = iter->data;

    g_mutex_lock (&stream->fragment_download_lock);
    stream->cancelled = FALSE;
    g_mutex_unlock (&stream->fragment_download_lock);

    stream->last_ret = GST_FLOW_OK;
    gst_task_start (stream->download_task);
  }
}

static void
gst_adaptive_demux_stop_tasks (GstAdaptiveDemux * demux)
{
  GList *iter;

  gst_task_stop (demux->priv->updates_task);

  g_mutex_lock (&demux->priv->updates_timed_lock);
  demux->priv->stop_updates_task = TRUE;
  g_cond_signal (&demux->priv->updates_timed_cond);
  g_mutex_unlock (&demux->priv->updates_timed_lock);

  gst_uri_downloader_cancel (demux->downloader);

  for (iter = demux->streams; iter; iter = g_list_next (iter)) {
    GstAdaptiveDemuxStream *stream = iter->data;

    g_mutex_lock (&stream->fragment_download_lock);
    stream->cancelled = TRUE;
    gst_task_stop (stream->download_task);
    g_cond_signal (&stream->fragment_download_cond);
    g_mutex_unlock (&stream->fragment_download_lock);
  }

  g_mutex_lock (&demux->priv->manifest_update_lock);
  g_cond_broadcast (&demux->priv->manifest_cond);
  g_mutex_unlock (&demux->priv->manifest_update_lock);

  /* need to release manifest_lock before stopping the src element.
   * The streams were asked to cancel, so they will not make any writes to demux
   * object. Even if we temporarily release manifest_lock, the demux->streams
   * cannot change and iter cannot be invalidated.
   */
  for (iter = demux->streams; iter; iter = g_list_next (iter)) {
    GstAdaptiveDemuxStream *stream = iter->data;
    GstElement *src = stream->src;

    GST_MANIFEST_UNLOCK (demux);

    if (src) {
      gst_element_set_state (src, GST_STATE_READY);
    }

    /* stream->download_task value never changes, so it is safe to read it
     * outside critical section
     */
    gst_task_join (stream->download_task);

    GST_MANIFEST_LOCK (demux);
  }

  GST_MANIFEST_UNLOCK (demux);

  /* demux->priv->updates_task value never changes, so it is safe to read it
   * outside critical section
   */
  gst_task_join (demux->priv->updates_task);

  GST_MANIFEST_LOCK (demux);

  for (iter = demux->streams; iter; iter = g_list_next (iter)) {
    GstAdaptiveDemuxStream *stream = iter->data;

    stream->download_error_count = 0;
    stream->need_header = TRUE;
    gst_adapter_clear (stream->adapter);
  }
}

That is when stopping tasks, it dose the download cancelling but when starting tasks, it dosen't do the download resetting. Is this reasonable?

Besides, I don't know how to decompile the SDK to source code in order to modify.

[Sebastian Dröge-3]

On Mi, 2016-07-06 at 01:12 -0700, silver wrote:
> 
> That is when stopping tasks, it dose the download cancelling but when
> starting tasks, it dosen't do the download resetting. Is this
> reasonable?

Well, it sounds like it would be reasonable to reset the downloader
when starting the tasks again. Does that solve your problem?

> Besides, I don't know how to decompile the SDK to source code in
> order to modify.

For which platform do you want to build?

--

Sebastian Dröge, Centricular Ltd · http://www.centricular.com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Xinheng]

I think it might be the key to solve my problem but I don't know how to extract the source code from actual downloaded SDK (for Android and iOS) and also it is not clear to build from source code with those plugins I need even if I had a look at the README in cerbero.

[Sebastian Dröge-3]

On Mi, 2016-07-06 at 23:25 -0700, silver wrote:
> I think it might be the key to solve my problem but I don't know how to
> extract the source code from actual downloaded SDK (for Android and iOS) and
> also it is not clear to build from source code with those plugins I need
> even if I had a look at the README in cerbero.

Please just file a bug with all the details then, and also a sample
stream.

In general it will be easier to build on a normal platform for this
kind of development, i.e. Linux, OSX or Windows. You can use cerbero
for that or not.

In the case of cerbero you would first "package gstreamer-1.0", then
you have all sources in the build/sources directory. You could then
update the recipe (in the recipes directory) to point to a local GIT
branch with your changes, rebuild that one with the buildone command
and package again to get a new package with your changes.

--

Sebastian Dröge, Centricular Ltd · http://www.centricular.com
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Xinheng]

I tried the command gstreamer-1.0 but it got the source in version 1.9. I'm now using 1.8.1. how can I get it?

Of course I will file a bug later but as I mentioned at the first time, it's difficult to provide a sample stream.