Cannot play from ampache subsonic server: Can't typefind stream - Playlist finished (wrong song id in constructed URI)

markuswernig commented 6 years ago

Before posting

Please follow the steps below and check the boxes with [x] once you did the step.

[x ] I checked the issue tracker for similar issues
[ x] I checked the changelog if the issue is already resolved
[ ] I tried the latest Clementine build from here This I didn't, because there is no build for my distro (Gentoo)

System information

Please provide information about your system and the version of Clementine used.

Operating System: Gentoo Linux amd64, openrc, QT5
Clementine version: 1.3.1_p20180416

Expected behaviour / actual behaviour

I added a Subsonic server (which is actually an ampache instance), added its root CA cert to /etc/ssl/certs/ca-certificates.crt (this solves #5360) I can load the catalogue, though no cover art is added. Playing any song from the catalogue immediately terminates with the dreaded "Playlist finished" message.

Obviously, it should play the song.

Steps to reproduce the problem (only for bugs)

Install (emerge) clementine, add subsonic server and attempt playing.

Analysis

On the same client machine I also have Debian stretch, which installs version 1.3.1+git276-g3485bbe43+dfsg-1. There playing from the very same ampache server works. So I went and checked the differences:

Debian links against QT4, while Gentoo links against QT5.

Debian has all available plugins compiled in, Gentoo (selectively) very few.

The root of the problem becomes clear from the ampache log file:

Gentoo (not working): 192.168.10.148 - - [10/Jun/2018:15:49:45 +0200] "GET /rest/getCoverArt.view?id=300008256 HTTP/1.1" 200 4353 "-" "Clementine 1.3.1" 192.168.10.148 - - [10/Jun/2018:15:49:45 +0200] "GET /rest/stream.view?v=1.8.0&c=Clementine&u=NNN&p=enc:PPP&id=17.225.195.64 HTTP/1.1" 200 4100 "-" "Clementine 1.3.1"

Debian (working): 192.168.10.187 - - [10/Jun/2018:15:50:45 +0200] "GET /play/index.php?ssid=ffff&type=song&oid=8256&uid=2&client=Clementine&noscrobble=1&player=api&name=Title.mp3 HTTP/1.1" 200 3942578 "-" "Clementine 1.3.1" 192.168.10.148 - - [10/Jun/2018:15:50:45 +0200] "GET /rest/stream.view?v=1.8.0&c=Clementine&u=NNN&p=enc:PPP&id=300008256 HTTP/1.1" 200 653352 "-" "Clementine 1.3.1"

(The order of the two log entries is inversed because ampache's rest api proxies the request to its player api, which then is the first to terminate and to log the request.)

So the difference is the "id" parameter in the request URI, which is wrong in the Gentoo build (id=17.225.195.64) but correct in the Debian build (id=300008256).

Strange thing is that the id is still correct in the preceding GET for the coverArt ...

The issue behind the wrong id seems to be a number conversion (inet_ntoa or similar) performed on it that should not take place: 17.225.195.64 = 0x11.0xE1.0xC3.0x40, and 0x11E1C340 = 300008256 !!! So something is taking the decimal 300008256 and converting it to an IP address ...

Attempting to download the file from the two URIs results in a 0 byte file with the wrong id, which can also be seen in the debugging output from gstreamer:

export GST_DEBUG=2,audio:5,stream:5,decode:5,typefind:8,soup:5,filesrc:8,uri*:8 clementine --verbose [...] 0:15:26.089065922 7436 0x7faa6c003d80 DEBUG souphttpsrc gstsouphttpsrc.c:1722:gst_soup_http_src_start: start("https://ampache.host.name/rest/stream.view?v=1.8.0&c=Clementine&u=NNN&p=enc:PPP&id=17.225.195.64") [...] 0:15:26.089135346 7436 0x7faa6c003d80 DEBUG souphttpsrc gstsouphttpsrc.c:1803:gst_soup_http_src_get_size: get_size() = FALSE 0:15:26.089143422 7436 0x7faa6c003d80 DEBUG souphttpsrc gstsouphttpsrc.c:1849:gst_soup_http_src_do_seek: do_seek(0-18446744073709551615) 0:15:26.089150027 7436 0x7faa6c003d80 DEBUG souphttpsrc gstsouphttpsrc.c:1854:gst_soup_http_src_do_seek: Seek to current read/end position and no seek pending 0:15:26.089222107 7436 0x7faa180028a0 DEBUG typefind gsttypefindelement.c:669:gst_type_find_element_sink_event: got stream-start event in mode 1 0:15:26.118705803 7436 0x7faa180028a0 INFO souphttpsrc gstsouphttpsrc.c:1033:gst_soup_http_src_got_headers: got headers 0:15:26.118745455 7436 0x7faa180028a0 DEBUG souphttpsrc gstsouphttpsrc.c:1081:gst_soup_http_src_got_headers: size = 0 0:15:26.118766632 7436 0x7faa180028a0 DEBUG souphttpsrc gstsouphttpsrc.c:1168:gst_soup_http_src_got_headers: Content-Type: text/html 0:15:26.118776677 7436 0x7faa180028a0 DEBUG souphttpsrc gstsouphttpsrc.c:1426:gst_soup_http_src_send_message: Successfully got a reply [...] 0:15:26.118819493 7436 0x7faa180028a0 DEBUG souphttpsrc gstsouphttpsrc.c:1589:gst_soup_http_src_read_buffer: Read 0 bytes from http input 0:15:26.118828899 7436 0x7faa180028a0 DEBUG souphttpsrc gstsouphttpsrc.c:1698:gst_soup_http_src_create: Returning -3 eos 0:15:26.119006357 7436 0x7faa180028a0 DEBUG typefind gsttypefindelement.c:669:gst_type_find_element_sink_event: got eos event in mode 1 0:15:26.119021050 7436 0x7faa180028a0 INFO typefind gsttypefindelement.c:701:gst_type_find_element_sink_event: Got EOS and no type found yet 0:15:26.119031102 7436 0x7faa180028a0 WARN typefind gsttypefindelement.c:991:gst_type_find_element_chain_do_typefinding: error: Stream doesn't contain enough data. 0:15:26.119038274 7436 0x7faa180028a0 WARN typefind gsttypefindelement.c:991:gst_type_find_element_chain_do_typefinding: error: Can't typefind stream 15:49:45.630 ERROR GstEnginePipeline:652 2 "/var/tmp/portage/media-libs/gstreamer-1.12.4/work/gstreamer-1.12.4/plugins/elements/gsttypefindelement.c(991): gst_type_find_element_chain_do_typefinding (): /GstPipeline:pipeline/GstURIDecodeBin:uridecodebin-15/GstTypeFindElement:typefindelement1:\nCan't typefind stream" 15:49:45.631 WARN GstEngine:693 Gstreamer error: "Stream doesn't contain enough data."

Content-type text/html and size 0 is the same result that wget gives with the wrong id in the URI.

hatstand commented 6 years ago

Likely due to a behaviour change in qurl between 4 & 5

pinealservo commented 6 years ago

I just looked into this, since it just bit me after a system upgrade; it's almost certainly what @hatstand suggested. The Qt-5 docs on QUrl are very adamant about the host component of a QUrl being a proper STD 3 hostname; the parser is trying very hard to turn QUrl url = QUrl(QString("subsonic://%1").arg(id)); into a URL with a valid hostname.

Based on the documentation, I think this could be resolved with a slight change of the URL format to the following: QUrl url = QUrl(QString("subsonic:%1").arg(id)); which puts the URL in the "non-hierarchical" category and would place the id in the path component instead of host, which should dissuade it from trying to interpret the integer as an IP address.

I will attempt a patch myself and submit a pull request if it works out, but I won't be offended if someone more familiar with the codebase takes it on and fixes it before then.

cquike commented 4 years ago

Hi, Just for reference: I am using a similar setup, ampache 4.0.1 and a Debian buster client with QT 5.11.3. This is working properly for me, both using the clementine package from Debian (1.3.1+git609-g623a53681+dfsg-1) and clementine compiled from the latest git.

markuswernig commented 4 years ago

Hi

Yes, ampache has been patched to work around this particular bug, so this will work even if the ID sent by clementine is still in the wrong format. I have not, however, checked recently if that is still the case (i.e if that bug still exists in clementine). You may want to look at the ampache access logs.

best /m

On 12/5/19 12:15 AM, cquike wrote:

Hi, Just for reference: I am using a similar setup, ampache 4.0.1 and a Debian buster client with QT 5.11.3. This is working properly for me, both using the clementine package from Debian (1.3.1+git609-g623a53681+dfsg-1) and clementine compiled from the latest git

cquike commented 4 years ago

The logs show the id as it should be: 192.168.11.11 - - [05/Dec/2019:00:04:16 +0100] "GET /rest/stream.view?v=1.8.0&c=Clementine&u=uuu&p=enc:ppp&id=300006272 HTTP/1.0" 200 1204766 "-" "Clementine 1.3.1-945-g440ac6dda"

Maybe QT 5.11.3 has fixed the issue in QUrl?

markuswernig commented 4 years ago

On 12/5/19 12:33 AM, cquike wrote:

The logs show the id as it should be: |192.168.11.11 - - [05/Dec/2019:00:04:16 +0100] "GET /rest/stream.view?v=1.8.0&c=Clementine&u=uuu&p=enc:ppp&id=300006272 HTTP/1.0" 200 1204766 "-" "Clementine 1.3.1-945-g440ac6dda"|

Maybe QT 5.11.3 has fixed the issue in QUrl?

That looks good, indeed. So maybe if somebody else can confirm that (I cannot, currently) then we can close this bug?

clementine-player / Clementine