Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Google Play music intermittently cutting songs short #547

Closed
driador opened this Issue Jan 8, 2019 · 17 comments

Comments

Projects
None yet
5 participants
@driador
Copy link

driador commented Jan 8, 2019

Greetings!

Playing an album (not in my collection) via the --gmusic-unlimited-album option, tizonia is cutting some songs short and skips to the next song. As best as I can tell, this is occurring randomly in the song, and not at a fixed location (ie, five seconds before the song ends, etc).

Tizonia version: 0.15.0 running on Ubuntu 18.04 Server.

If there's any way to enable verbose logging I would be happy to provide any debugging information required, short of credentials ;).

Thanks in advance!
Reuben

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Jan 8, 2019

Hi!, thanks for stopping by.

I seem to recall that a problem like that was fixed in 0.16.0. Any chance that you could upgrade Tizonia on your server and see if the problem goes away?

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Jan 8, 2019

I believe #500 used to produce this effect. I.e. the connection was lost while streaming a song and Tizonia would skip to the next song in the queue. I believe 0.16.0 should improve on that front.

@driador

This comment has been minimized.

Copy link
Author

driador commented Jan 8, 2019

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Jan 8, 2019

Reuben, thanks for offering to help out with this,

Our links here have redundant connectivity and generally do not suffer drops.

Actually, it wasn't exactly a dropped link type of thing, but a strange glitch in either libcurl or the underlying TLS implementation.

In my case, I found it with GnuTLS

libcurl : [SSL re-using session ID
libcurl : [gnutls_handshake() failed: An unexpected TLS packet was received.
libcurl : [stopped the pause stream!
libcurl : [Closing connection 28

The issue manifested itself when the currently playing stream was fully downloaded and the connection to download the next song was starting to be negotiated. At the point, the TLS layer threw a handshake error as shown above. This was happening in 1 in 25-30 songs. When that event was detected Tizonia would immediately skip to the next song, interrupting the playback of the current song. This is not ideal. The ideal behaviour would have been to wait until the data in the current stream (which is fully downloaded at that point) is fully decoded and renderered and only take action in that moment. Instead, the playback pipeline is flushed and that is why you experience the cuts.

The fixes delivered in 0.16.0 were successful in preventing the handshake errors, at least in my environment. But it may be that your environment is able to reproduce them somehow.

In my Ubuntu 18.04 64-bit desktop, I'm running with the following version of libcurl:

libcurl/7.58.0 GnuTLS/3.5.18 zlib/1.2.11 libidn2/2.0.4 libpsl/0.19.1 (+libidn2/2.0.4) nghttp2/1.30.0 librtmp/2.3

Here is a logging configuration file.
dotlog4crc.tar.gz

If you extract it on your $HOME directory, you should end up with the file $HOME/.log4crc

With that file there, Tizonia will output to /tmp/tizonia.log the messages of the module that uses libcurl. There will be a message like the above, stating which version of libcurl is in use. If the tls handshake error appears, we will be able to see it there as well (note that the log file will be rotated up to 10 times if it grows too large).

@driador

This comment has been minimized.

Copy link
Author

driador commented Jan 9, 2019

Good morning,

Here's the log file from this morning when the skip occurred for me. I didn't see anything out of the ordinary, unless I'm completely missing it.

tizonia.log

@croxis

This comment has been minimized.

Copy link

croxis commented Feb 1, 2019

Hello! I am having the same issue with 0.17on arch linux (built through the AUR). I've tried using the dotlog config above but it is not outputting to thetmp directory.

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Feb 2, 2019

@djsiddz2 @croxis

Sorry for the slow response. Yes, I've also seen this in my own tests. The streams are interrupted because of this GnuTLS error:

09-01-2019 16:04:30.631 - [PID:3262][TID:3309] [TRACE] [tiz.platform.urltrans] [tizurltransfer.c:curl_debug_cback:794] --- libcurl : [GnuTLS recv error (-54): Error in the pull function.

I've seen this problem referenced in the curl bug tracker, and they dismissed it as network/env issue, assumed to be unrelated to curl:
curl/curl#1707

Tizonia could possibly try to play more of the stream since at least a part of it is still buffered when the error arrives. But there probably isn't much Tizonia can do to avoid the error in the first place.

I'll keep this open for a while, in case we can find some other evidence.

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Feb 2, 2019

I've reviewed the code and actually, Tizonia consumes all the data from its buffers correctly, i.e. it keeps playing all the buffered data even after the error occurs. This can be easily observed because the GnuTLS error appears in the log and the song gets cut a few seconds (15-20) later.

There is not much else that can be done.

@driador

This comment has been minimized.

Copy link
Author

driador commented Feb 2, 2019

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Feb 2, 2019

Thr GnuTLS error (-54) is there in your log (see line 6400). But note that this is not the error that I was talking about at the beginning of this thread. It is the first time I see -54. It has the same effect as the GnuTLS handshake error though.

@timothynott

This comment has been minimized.

Copy link

timothynott commented Feb 22, 2019

I'm trying to track down what may be the same error. I can't get the ~/.log4crc config to work. Nothing is showing up in /tmp/tizonia.log

I have it in my $HOME directory

@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Feb 26, 2019

Hi @timothynott

Do you have Snap or a Debian installation? With the Snap install, the $HOME directory seen by the application is different, so you would need:
$HOME/snap/tizonia/current/.log4crc

Also, with Snap's strict confinement (as used by Tizonia), you might want to change the target location to something under $HOME/snap/tizonia/current/, in case /tmp/tizonia.log might not be writable.

@timothynott

This comment has been minimized.

Copy link

timothynott commented Feb 26, 2019

@tizonia Thanks for the help! Yes, I am using the snap.

Attaching my log file. I included the whole thing from the beginning. I skipped a few songs to get to a short one, but this happens with all of them. Things get interesting at "26-02-2019 15:53:01.786" -- looks like the same error followed by about 25 seconds of playback and then cutting out and proceeding to the next song.

The regularity with which this happens makes me think it may be a calculation error rather than an actual TLS error -- as if curl is asking for bits that do not exist. An actual TLS error would not account for every song being clipped by about 30 seconds every time.

tizonia.log.zip

Curl folks are discounting this as a network error, which it may be. If one asks for something that is not there, it will result in an error. Is there anything specific to how Tizonia is determining how to make the request that could account for the error?

@juanrubio

This comment has been minimized.

Copy link
Collaborator

juanrubio commented Mar 6, 2019

@timothynott

The regularity with which this happens makes me think it may be a calculation error rather than an actual TLS error

Thanks for reminding me about this detail. I think you are right. There is a clear pattern. It may be that the Google servers now do not like to keep the connection open for too long. It is possible that they expect the client to be as greedy as possible to download and buffer the stream quickly rather than keeping the connection open for longer periods of time.

Tizonia currently is not greedy in that sense, and it does not pull the data quickly. I'm changing that now and my initial tests show good results. I will report back when I have something more definitive.

@tizonia tizonia added the bug label Mar 6, 2019

@tizonia tizonia added this to the v0.18.0 milestone Mar 6, 2019

@juanrubio

This comment has been minimized.

Copy link
Collaborator

juanrubio commented Mar 6, 2019

Google servers now do not like to keep the connection open for too long

This assumption was right. Tizonia is currently buffering about 40 seconds of data, with further requests being put out periodically as the internal buffer utilization falls below a low watermark level. When increasing the capacity of the buffer e.g. to let's say 10 min, the occurrence of the '-54' error disappears.

I'm thinking to expose a configuration element to make the size of the buffer configurable in seconds, something like:

  • tizonia.conf
gmusic.cache_seconds = 600
  • and from command-line:
tizonia --gmusic-unlimited-artist 'queen' --gmusic-cache-seconds=600
@timothynott

This comment has been minimized.

Copy link

timothynott commented Mar 6, 2019

@juanrubio Nice detective work!

juanrubio added a commit that referenced this issue Mar 8, 2019

juanrubio added a commit that referenced this issue Mar 8, 2019

juanrubio added a commit that referenced this issue Mar 12, 2019

config/src/tizonia.conf.in: added 'buffer_seconds' configuration elem…
…ent for

gmusic, scloud, dirble, youtube and plex (#547)

juanrubio added a commit that referenced this issue Mar 12, 2019

http_source: use default values for 'buffer_seconds' configuration el…
…ements in gmusic, scloud, dirble, youtube and plex (#547)

juanrubio added a commit that referenced this issue Mar 12, 2019

player: added '--buffer-seconds' configuration option to tweak buffer…
…ing in gmusic, scloud, dirble, youtube and plex (#547)
@tizonia

This comment has been minimized.

Copy link
Owner

tizonia commented Mar 12, 2019

OK, the changes are now in the develop branch. They will be merged to trunk before release (no date yet, but soon enough).

The following configuration elements have been added to tizonia.conf (see 5bd9cc1). These are optional elements and there are internal defaults in the code that should prevent cuts in the normals cases (e.g. gmusic tracks of 10 min or less).

gmusic.buffer_seconds
soundcloud.buffer_seconds
dirble.buffer_seconds
youtube.buffer_seconds
plex.buffer_seconds

Also, these values can be set from the command-line with the --buffer-seconds command-line options, e.g:

$ tizonia --gmusic-unlimited-artist 'queen' --buffer-seconds=520
$ tizonia --soundcloud-genres 'piano' --buffer-seconds=720
etc...

@juanrubio juanrubio closed this in 53074e7 Mar 13, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.