Skip to content

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

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

Handling 302 redirects from Google Music #232

Closed
alcoheca opened this issue Jan 18, 2019 · 39 comments
Closed

Handling 302 redirects from Google Music #232

alcoheca opened this issue Jan 18, 2019 · 39 comments
Assignees

Comments

@alcoheca
Copy link

alcoheca commented Jan 18, 2019

Hello,

I'm trying to diagnose an issue in squeezebox-googlemusic (squeezebox-googlemusic/squeezebox-googlemusic#21) which I think is a problem with LMS core.

Certain tracks never play in LMS, while the url is valid and the song can play in a browser for instance.

Here are two logs the first with a failed request, the second with a successful request. It looks like the track the doesn't work involve a redirect, while the second track which doesn't redirect plays normally.

Not working

[19-01-18 13:53:25.8364] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22 HTTP/1.0
[19-01-18 13:53:25.8585] Slim::Formats::RemoteStream::request (148) Response: HTTP/1.1 302 Found
[19-01-18 13:53:25.8889] Slim::Formats::RemoteStream::request (197) Redirect to: https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22&ir=1&rr=12
[19-01-18 13:53:25.8903] Slim::Formats::RemoteStream::open (70) Opening connection to https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22&ir=1&rr=12: [r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22&ir=1&rr=12 with timeout 15]
[19-01-18 13:53:25.9408] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22&ir=1&rr=12 HTTP/1.0
[19-01-18 13:53:25.9612] Slim::Formats::RemoteStream::request (148) Response:
[19-01-18 13:53:25.9620] Slim::Formats::RemoteStream::request (152) Warning: Invalid response code () from remote stream https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=VdpBXMC1A8bGcaOnvdAE&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=HUF610HTpmQYQ2YCLwh88g&ip=151.231.134.54&ipbits=0&expire=1547819695&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=0FDDD4BD78D747C7E57CD1EA82B48E42E35650EA.136F1A0FF6BC893AC64D0978BA95086F0D6A5DA7&key=cms1&initcwndbps=9610&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547819582&mv=m&pl=22&ir=1&rr=12

Working track

[19-01-18 13:53:30.6231] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=3b5a11f6d38cb528&itag=25&source=skyjam&begin=0&ei=WdpBXNidMs2fc56BifgJ&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=nZAfJO0_xWATmeH57hLEKQ&ip=151.231.134.54&ipbits=0&expire=1547819699&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=013F251F416F993FD58F81556B65F63D0C5116CA.386DEF20FB99AB9D3F0419B0CD0A417C6D9DC253&key=cms1&initcwndbps=8850&mm=31&mn=sn-cn3tc-ba5l&ms=au&mt=1547819476&mv=m&pl=22 HTTP/1.0
[19-01-18 13:53:30.7090] Slim::Formats::RemoteStream::request (148) Response: HTTP/1.1 200 OK
[19-01-18 13:53:30.7451] Slim::Formats::RemoteStream::request (209) Opened stream!

I'm running LMS nightly: Logitech Media Server Version: 7.9.2 - 1545112045 @ Tue Dec 18 07:17:41 CET 2018.

Does anyone have any ideas what might be up with this? We're having a party on the weekend and just realised that my house wide sound system is skipping some of my favourite songs! :-(

@mherger
Copy link
Contributor

mherger commented Jan 18, 2019

Would there be other Opening connection... lines before the first line in each segment you posted?

@mherger mherger self-assigned this Jan 18, 2019
@alcoheca
Copy link
Author

thanks for looking into this!

This is everything that is displayed with player.streaming.remote logging set to debug

(this is a failed play)

If you need further logging tell what to enable in Advanced -> Logging.

[19-01-18 14:21:11.5378] Slim::Player::Protocols::HTTPS::new (27) Opening connection to https://r3---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22: [r3---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22 with timeout 15]
[19-01-18 14:21:11.6736] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22 HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: */*
Host: r3---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com:443
User-Agent: iTunes/4.7.1 (Linux; N; Debian; armv7l-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1545112045
Icy-Metadata: 1

[19-01-18 14:21:11.6971] Slim::Formats::RemoteStream::request (148) Response: HTTP/1.1 302 Found
[19-01-18 14:21:11.7562] Slim::Formats::RemoteStream::request (197) Redirect to: https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22&ir=1&rr=12
[19-01-18 14:21:11.7586] Slim::Formats::RemoteStream::open (70) Opening connection to https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22&ir=1&rr=12: [r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22&ir=1&rr=12 with timeout 15]
[19-01-18 14:21:11.8112] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22&ir=1&rr=12 HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: */*
Host: r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com:443
User-Agent: iTunes/4.7.1 (Linux; N; Debian; armv7l-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1545112045
Icy-Metadata: 1

[19-01-18 14:21:11.8313] Slim::Formats::RemoteStream::request (148) Response:
[19-01-18 14:21:11.8471] Slim::Formats::RemoteStream::request (152) Warning: Invalid response code () from remote stream https://r1---sn-cn3tc-ba5s.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=227d53aead755512&itag=25&source=skyjam&begin=0&ei=1uBBXMjDNcmjc8qiqogP&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=UNz_s3-SnN0RJajYRAPsTQ&ip=151.231.134.54&ipbits=0&expire=1547821360&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=4E0B3433C807BA02943A772AB076223E831C7E33.7CA4DC313D9833F7386DC7FB59086ADBFFCB1F24&key=cms1&initcwndbps=8900&mm=31&mn=sn-cn3tc-ba5s&ms=au&mt=1547821083&mv=m&pl=22&ir=1&rr=12
[19-01-18 14:21:11.8481] Slim::Player::Song::open (472) Warning: stream failed to open [googlemusic:track:Tgy2arqs6d4wpnvcrouirnrhyua].

@alcoheca
Copy link
Author

This is a successful play:

[19-01-18 14:23:56.4225] Slim::Player::Protocols::HTTPS::new (27) Opening connection to https://r6---sn-cn3tc-ba5l.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=3b5a11f6d38cb528&itag=25&source=skyjam&begin=0&ei=e-FBXPjCMInfcqmgnLAJ&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=xH372OhZM6ow01Vh9O2lTQ&ip=151.231.134.54&ipbits=0&expire=1547821525&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=25BBB4DEEFF987C360986853F493D4E0251A8143.396763DB724EE01D0E44DF238CDD021E56EE8620&key=cms1&initcwndbps=9340&mm=31&mn=sn-cn3tc-ba5l&ms=au&mt=1547821332&mv=m&pl=22: [r6---sn-cn3tc-ba5l.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=3b5a11f6d38cb528&itag=25&source=skyjam&begin=0&ei=e-FBXPjCMInfcqmgnLAJ&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=xH372OhZM6ow01Vh9O2lTQ&ip=151.231.134.54&ipbits=0&expire=1547821525&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=25BBB4DEEFF987C360986853F493D4E0251A8143.396763DB724EE01D0E44DF238CDD021E56EE8620&key=cms1&initcwndbps=9340&mm=31&mn=sn-cn3tc-ba5l&ms=au&mt=1547821332&mv=m&pl=22 with timeout 15]
[19-01-18 14:23:56.5295] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=3b5a11f6d38cb528&itag=25&source=skyjam&begin=0&ei=e-FBXPjCMInfcqmgnLAJ&o=06088474255084620519&cmbypass=yes&ratebypass=yes&cpn=xH372OhZM6ow01Vh9O2lTQ&ip=151.231.134.54&ipbits=0&expire=1547821525&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mm,mn,ms,mv,o,pl,ratebypass,source&signature=25BBB4DEEFF987C360986853F493D4E0251A8143.396763DB724EE01D0E44DF238CDD021E56EE8620&key=cms1&initcwndbps=9340&mm=31&mn=sn-cn3tc-ba5l&ms=au&mt=1547821332&mv=m&pl=22 HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: */*
Host: r6---sn-cn3tc-ba5l.c.doc-0-0-sj.sj.googleusercontent.com:443
User-Agent: iTunes/4.7.1 (Linux; N; Debian; armv7l-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1545112045
Icy-Metadata: 1

[19-01-18 14:23:56.5919] Slim::Formats::RemoteStream::request (148) Response: HTTP/1.1 200 OK
[19-01-18 14:23:56.6221] Slim::Formats::RemoteStream::request (209) Opened stream!

@alcoheca
Copy link
Author

So yes it looks like the Opening connection to line is different, perhaps some parsing problem in the plugin?

@mherger
Copy link
Contributor

mherger commented Jan 18, 2019

The only difference I'm seeing is the host name - which shouldn't hurt. Do you see anything else.

This sounds similar to what I've heard from some Pandora users. If only I had a way to reproduce this! Would you know of anyway to see this behaviour with something other than Google Music?

@alcoheca
Copy link
Author

Yeah you're right sorry I saw this m&pl=22: [r6---s with a gap, and thought that it only appeared in the first log. My bad.

I can share you my login details privately if that would help? Just be aware that I listen to a lot of Disney soundtracks due to having a young family.

@mherger
Copy link
Contributor

mherger commented Jan 18, 2019

If those tracks fail to stream, then I don't have to care about them anyway 😁. Yeah, that would be helpful!

@alcoheca
Copy link
Author

Have emailed you the plugin prefs file

@mherger
Copy link
Contributor

mherger commented Jan 18, 2019

Ugh... just tried to install the pre-requisities for the GMusic plugin... and Python fails on the first step already :-(

@alcoheca
Copy link
Author

Is it the sudo pip install gmusicapi==10.1.2 step? I just use the latest gmusicapi (12.0.0)

@mherger
Copy link
Contributor

mherger commented Jan 18, 2019

Got "Twin Peaks - Fire Walk With Me" playing. That's a good start 😀.

Would you know about some track reliably failing?

@Bucklew
Copy link

Bucklew commented Jan 21, 2019

Hello Michael,

there is no real dependency on the track, it just happens randomly after playing several tracks. Maybe pick an album from "Die drei ???", the streaming tracks are very short and it happens a lot more.

I actually tried to fix this bug on the plugin side, but that did not work. The plugin always gets a 200-Response and then afterwards the LMS core, when trying to stream the media, gets the unknown response code.

If the response code is unknown it is also persistent for a short period of time, e.g. when a track fails to open the next one will work, but if you are immediately skipping back to the broken track, it will fail again. You need 2-3 skip backs and maybe around 60 seconds, before the track actually plays.

Hope that helps a bit....? It is not easy to reproduce this issue.

@mherger
Copy link
Contributor

mherger commented Jan 23, 2019

I'm 128 tracks in to a "Die drei ???" session. No hiccup so far...

May I ask you what country you're in, and what ISP you're using? One dev reported similar issues with Pandora, but limited to only some ISPs.

@Bucklew
Copy link

Bucklew commented Jan 23, 2019

In my case UnityMedia with DualStack (IPv4/IPv6).

If you give me the needed debug levels, I can trace the issue for you.

@michaelherger
Copy link
Member

@alcoheca mentioned the required player.streaming.remote. Alas the output isn't good enough yet. And I don't even know yet what additional logging to add... There are still many more ??? albums I can play today :-).

@michaelherger
Copy link
Member

Ok, another 120 tracks played without any hiccup. There must be a more efficient way to reproduce this...

What platforms and operating systems are you running your LMS on? I only tested on macOS so far. Windows isn't an option anyway, is it?

@Bucklew
Copy link

Bucklew commented Jan 24, 2019

Reproduced it after 22 Songs:

[19-01-24 15:01:38.4205] Slim::Player::Protocols::HTTPS::new (27) Opening connection to https://r2---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=d1c56142cb6021e4&....: [r2---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=d1c56142cb6021e4&.... with timeout 15]
[19-01-24 15:01:38.5620] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=d1c56142cb6021e4&.... HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: /
Host: r2---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com:443
User-Agent: iTunes/4.7.1 (Linux; N; Debian; x86_64-linux; DE; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1548160716
Icy-Metadata: 1

[19-01-24 15:01:38.5788] Slim::Formats::RemoteStream::request (148) Response: HTTP/1.1 302 Found
[19-01-24 15:01:38.6941] Slim::Formats::RemoteStream::request (197) Redirect to: https://r4---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=d1c56142cb6021e4&....
[19-01-24 15:01:38.6948] Slim::Formats::RemoteStream::open (70) Opening connection to https://r4---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=d1c56142cb6021e4&...: [r4---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com on port 443 with path /videoplayback?id=d1c56142cb6021e4&.... with timeout 15]
[19-01-24 15:01:38.7705] Slim::Formats::RemoteStream::request (141) Request: GET /videoplayback?id=d1c56142cb6021e4&..... HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: /
Host: r4---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com:443
User-Agent: iTunes/4.7.1 (Linux; N; Debian; x86_64-linux; DE; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1548160716
Icy-Metadata: 1

[19-01-24 15:01:38.7880] Slim::Formats::RemoteStream::request (148) Response:
[19-01-24 15:01:38.7883] Slim::Formats::RemoteStream::request (152) Warning: Invalid response code () from remote stream https://r4---sn-4g5e6nl6.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=d1c56142cb6021e4&......
[19-01-24 15:01:38.7900] Slim::Player::Song::open (472) Warning: stream failed to open [googlemusic:track:Te2encp5nzlz67cpmkuy3p4cofe].

(Repeats three times)

Happens on Ubuntu 18.04.01 LTS.

@Bucklew
Copy link

Bucklew commented Jan 24, 2019

Interesting: The new URL from the 302 redirect features not only a new hostname, but also the new options "&ir=1&rr=12" on the end.

Maybe those options are leading to a problem?!

@alcoheca
Copy link
Author

Hi sorry I didn't get any notification of these questions.

Please try the Goblin album I mentioned in the plugins issue linked above.

@alcoheca
Copy link
Author

It's not random, it happens on specific tracks.

@alcoheca
Copy link
Author

@michaelherger I'm in the UK. And running LMS on a raspberry pi.

@Bucklew
Copy link

Bucklew commented Jan 28, 2019

Well, tried again and this time it happend on the eight track - which it did not last week. So maybe there a specific tracks, but it is not consistent.

The requests fails 3 times (always 302, then no response after the redirect), the server switches to the next track and if you switch back to the failed track, it works again - because you are getting a new URL on another host.

@mherger: Might it be possible to not only retry the failed URL, but to get a new URL from the googlemusic plugin? That would prevent this error I think. But i am not deep enough in the code, to know how to achieve this behavior to try it out.

btw: The failing track is this one:
https://play.google.com/music/m/Tzylj53teceatoxmibskv22cmtq?t=Und_die_Geisterlampe_Teil_08_-_Die_drei_

@alcoheca
Copy link
Author

For me even switching back after a successful track doesn't work. The tracks that I am unable to play never work. Pretty strange indeed!

@Bucklew
Copy link

Bucklew commented Jan 29, 2019

@alcoheca Have you tried it several times to play an non-functional track?

@alcoheca
Copy link
Author

@Bucklew yes I just tried playing that Goblin track 12 times and it still didn't work

@alcoheca
Copy link
Author

alcoheca commented Feb 6, 2019

@mherger Anything more you need or is it possible to reproduce using that song I mentioned?

@mherger
Copy link
Contributor

mherger commented Feb 6, 2019

@alcoheca Time, I need time :-). I haven't been at my desk for almost two weeks.

@alcoheca
Copy link
Author

alcoheca commented Feb 6, 2019

Yes I could do with some of that too. Sorry to hassle you!

@michaelherger
Copy link
Member

I'm sorry to say that that Goblin album plays just fine here, too. And no re-direct is involved...

What version of IO::Socket::SSL are you using (see Settings/Information in LMS)? I wonder whether the redirect, or the failure thereof, is due to outdated SSL libraries or something.

@Bucklew
Copy link

Bucklew commented Feb 8, 2019

@michaelherger

My informations:

Logitech Media Server Version: 7.9.2 - 1548427341 @ Fri Jan 25 16:17:35 CET 2019
Hostname: xx
IP-Adresse des Servers: x.x.x.x
Server-HTTP-Portnummer: 9000
Betriebssystem: Debian - DE - utf8
Plattformarchitektur: x86_64-linux
Perl-Version: 5.26.1 - x86_64-linux-gnu-thread-multi
Audio::Scan: 0.95
IO::Socket::SSL: 2.056
Datenbankversion: DBD::SQLite 1.58 (sqlite 3.22.0)
Anzahl erkannter Player: 3

@michaelherger
Copy link
Member

Crap... one more theory down: I'm at 1.966...

@Bucklew
Copy link

Bucklew commented Feb 8, 2019

Maybe too new? ;)

What about my idea to request a new URL from the gmusicapi, instead of trying the failing URL over and over again?

@mherger
Copy link
Contributor

mherger commented Feb 8, 2019 via email

@Bucklew
Copy link

Bucklew commented Feb 8, 2019

Up to the plugin author. But what tells you that this wouldn't end up in a get failing URL loop?...

Because in my experience after 2-3 tries google serves a new URL which works.

The Squeezeserver would skip the file after a 60 seconds timeout.

@alcoheca
Copy link
Author

alcoheca commented Feb 8, 2019

Yeah I'm not sure a 60 second timeout is that helpful. There has to be something at work here. Can't check my lib versions are until later on but will report back.

@Bucklew I think we might be having different issues? Like I said, the songs which do not play for me NEVER play, despite numerous requests.

@alcoheca
Copy link
Author

alcoheca commented Feb 8, 2019

I'll try squeezeboxserver on a different operating system tonight.

@Bucklew
Copy link

Bucklew commented Feb 8, 2019

@alcoheca Do you get a 302 response and afterwards an empty response?

@alcoheca
Copy link
Author

alcoheca commented Feb 8, 2019

@Bucklew yes, see my logs and the title of this issue

@Bucklew
Copy link

Bucklew commented Feb 8, 2019

@alcoheca Then I guess we have a similar issue. The question would be how to resolve it.

Some people have zero empty responses, you have zero response every single time, I just got them sometimes.

@mherger mherger closed this as completed Feb 23, 2021
@LMS-Community LMS-Community locked and limited conversation to collaborators Feb 23, 2021

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants