Google Play music intermittently cutting songs short

[driador]

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]

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]

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]

On Tue, Jan 08, 2019 at 10:18:59AM -0800, Tizonia wrote:

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.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.*

Hello, thanks for the speedy reply. I just updated per the updating instructions and its still occurring. While the other issue is connection related, I question if this is exactly what's happening. Our links here have redundant connectivity and generally do not suffer drops.

That said, I have also confirmed that this occurs on multiple albums, just to rule out that perhaps it was the source itself.

Please let me know what else I can provide or do to help troubleshoot the issue, and thanks again. Reuben

[tizonia]

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]

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]

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]

@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: https://github.com/curl/curl/issues/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]

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]

The only thing I'm a bit confused on is I didn't see the TLS error in my logs that I attached above, that is, unless I'm completely daft or blind.

On Sat, Feb 2, 2019 at 1:57 PM Tizonia notifications@github.com wrote:

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.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/tizonia/tizonia-openmax-il/issues/547#issuecomment-459994537, or mute the thread https://github.com/notifications/unsubscribe-auth/AkWDlgfuZ0OWn_bgN4kVOI5VKsMBuT5nks5vJe2tgaJpZM4Z165Z .

[tizonia]

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]

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]

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]

@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]

@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.

[juanrubio]

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]

@juanrubio Nice detective work!

[tizonia]

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 5bd9cc16fdb23dbf4b3d5246db2b912700b007d8). 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...