Streaming actor blocking mopidy till 80minutes timeout

[SeppSTA]

Hi all,

I think there is a bug in the streaming actor during the unwrapping step if the first scan fails.

When the scan fails with an exception, the code continues and tries to download the streaming uri. When this uri is already the final stream uri it will for sure take a while to download the whole stream ;)

This is where the issue / bug comes in. The default timeout is 5000 and I think this should be ms. But the underlying request object uses seconds. So the code waits for more than 80 minutes to get the content and check if it is a playlist.

http://docs.python-requests.org/en/master/user/advanced/#request-and-response-objects

The connect timeout is the number of seconds Requests will wait for your client to establish a connection to a remote machine (corresponding to the connect()) call on the socket. It's a good practice to set connect timeouts to slightly larger than a multiple of 3, which is the default TCP packet retransmission window.

Once your client has connected to the server and sent the HTTP request, the read timeout is the number of seconds the client will wait for the server to send a response.

This is the debug output during the described failure (I added the "download URI" debug message to see the uri and timeout):

 Parsed playlist (http://www.wdr.de/wdrlive/media/mp3/wdr2-rhein-und-ruhr.m3u) and found new URI: http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf
DEBUG    2016-05-31 12:34:23,415 [12549:StreamBackend-3] mopidy.stream.actor
  Unwrapping stream from URI: http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf
0:13:18.639482765 12549 0xac0c1a90 WARN             souphttpsrc gstsouphttpsrc.c:1595:gst_soup_http_src_parse_status:<souphttpsrc27> error: Server sent bad data.
0:13:18.639981762 12549 0xac0c1a90 WARN             souphttpsrc gstsouphttpsrc.c:1595:gst_soup_http_src_parse_status:<souphttpsrc27> error: Message Corrupt (8), URL: http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf, Redirect to: (NULL)
0:13:18.642519078 12549 0xac0c1a90 WARN             souphttpsrc gstsouphttpsrc.c:1595:gst_soup_http_src_parse_status:<souphttpsrc27> error: Server sent bad data.
0:13:18.642963075 12549 0xac0c1a90 WARN             souphttpsrc gstsouphttpsrc.c:1595:gst_soup_http_src_parse_status:<souphttpsrc27> error: Message Corrupt (8), URL: http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf, Redirect to: (NULL)
0:13:18.643899318 12549 0xac0c1a90 WARN                 basesrc gstbasesrc.c:2948:gst_base_src_loop:<souphttpsrc27> error: Internal data flow error.
0:13:18.644302816 12549 0xac0c1a90 WARN                 basesrc gstbasesrc.c:2948:gst_base_src_loop:<souphttpsrc27> error: streaming task paused, reason error (-5)
DEBUG    2016-05-31 12:34:23,555 [12549:StreamBackend-3] mopidy.stream.actor
  GStreamer failed scanning URI (http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf): gst-resource-error-quark: Server sent bad data. (9)
DEBUG    2016-05-31 12:34:23,557 [12549:StreamBackend-3] mopidy.stream.actor
  download URI: http://wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net/7/371/119456/v1/gnl.akacast.akamaistream.net/wdr-mp3-m-wdr2-duesseldorf (4999.61145902ms)
INFO     2016-05-31 12:34:23,567 [12549:StreamBackend-3] requests.packages.urllib3.connectionpool
  Starting new HTTP connection (1): wdr-mp3-m-wdr2-duesseldorf.akacast.akamaistream.net

The bad part about this bug is, that for the next 80 minutes mopidy is busy downloading the content and is not reacting to any command. Even a service restart is failing cause the download is still ongoing and is blocking the shutdown.

This is the exception handler starting the issue:
https://github.com/mopidy/mopidy/blob/develop/mopidy/stream/actor.py#L125

I would suggest to reduce the timeout to seconds when calling the download
https://github.com/mopidy/mopidy/blob/develop/mopidy/stream/actor.py#L145

But I'm not familiar with the code to see where the timeout issue really starts.
Thank you very much for all your great work! :)

Cheers
Sebastian

[kingosticks]

Well spotted and thank you such a well researched bug report.

It should be fine to just call http.download() with download_timeout/1000. if you are interested in submitting a PR, please do.

[SeppSTA]

done :)

#1522

[camilonova]

@kingosticks Should be ready to merge and close this issue.

[camilonova]

@adamcik Can be closed now