Repository navigation
Shannon connection is not re-established on failure #88
Description
Sometimes the Shannon connection (whatever that is) breaks, and go-librespot becomes unusable:
ERRO[0961] did not receive last pong ack from accesspoint, 120s passed
ERRO[0961] failed receiving packet error="failed reading packet header: read tcp 10.65.42.112:51674->34.158.1.133:4070: use of closed network connection"
ERRO[2461] did not receive last pong from dealer, 60s passed
ERRO[2491] did not receive last pong from dealer, 90s passed
ERRO[2521] did not receive last pong from dealer, 120s passed
ERRO[2551] did not receive last pong from dealer, 150s passed
ERRO[2581] did not receive last pong from dealer, 180s passed
ERRO[2611] did not receive last pong from dealer, 210s passed
ERRO[2641] did not receive last pong from dealer, 240s passed
ERRO[2671] did not receive last pong from dealer, 270s passed
ERRO[2701] did not receive last pong from dealer, 300s passed
[...etc]
Here is another error:
ERRO[12016] failed receiving packet error="failed reading packet header: read tcp 10.65.42.112:55682->34.158.1.133:4070: read: connection reset by peer"
(this time without the "did not receive last pong from dealer" messages, though it did start to spew those messages when I tried, and failed, to connect to the go-librespot instance).
I inserted some debugging code, and the stack trace where this error is generated in both cases looks like this:
goroutine 87 [running]:
runtime/debug.Stack()
/usr/local/go/src/runtime/debug/stack.go:26 +0x64
runtime/debug.PrintStack()
/usr/local/go/src/runtime/debug/stack.go:18 +0x1c
github.com/devgianlu/go-librespot/ap.(*shannonConn).receivePacket(0x400040c0c0)
/home/ayke/src/go-librespot/ap/shannon.go:83 +0x1d8
github.com/devgianlu/go-librespot/ap.(*Accesspoint).recvLoop(0x40004e8410)
/home/ayke/src/go-librespot/ap/ap.go:251 +0x50
created by github.com/devgianlu/go-librespot/ap.(*Accesspoint).startReceiving.func1 in goroutine 1
/home/ayke/src/go-librespot/ap/ap.go:235 +0x8c
Looking at the code (AccessPoint.recvLoop) it looks like it is intended to reestablish the connection when an error occurs, but clearly it doesn't for me.
Reacted by Lazy-256
Activity
devgianlu commentedon Sep 10, 2024
I have observed this myself too, it was working fine before, I think it's a regression introduced by #69. I did not debug this yet because I am not able to reproduce it consistenly, just happens randomly on my device.
aykevl commentedon Sep 10, 2024
Can you describe how this is supposed to work? Then I might be able to develop a fix (I normally have a Spotifyd/librespot instance running 24/7 so I hit this frequently).
devgianlu commentedon Sep 10, 2024
There are two components called accesspoint (AP) and dealer that are persistent connections (TCP and Websocket). They both rely on a ping/pong (120 seconds for AP, 30 for dealer) mechanism to keep the server/client connected.
The idea behind that code is that if no ping/pong is received then the connection is closed causing the recv loop to fail and start reconnecting.
I think this is somewhat related to #48.
aykevl commentedon Sep 19, 2024
Investigated the issue a bit more.
This time the issue started exactly at the time I tried to connect to it from the Android app. It showed up in the list, I clicked it, and then it disappeared and after a bit (probably 60s) it started logging those error messages
did not receive last pong from dealer.Here the error message is generated, and the code that's supposed to close the connection:
go-librespot/dealer/dealer.go
Lines 134 to 139 in b95e6ac
The
recvLoopmeanwhile is stuck here:So apparently once the connection breaks it gets stuck in this channel receive operation?
go-librespot/dealer/recv.go
Lines 236 to 237 in b95e6ac
I'll add some debugging code to try to figure out why it gets stuck there.
devgianlu commentedon Sep 21, 2024
That's interesting, I've been looking at the wrong place for some time. I wonder where
AppPlayer.Runis stuck then, since it should always reply to the dealer requests.@aykevl Are you using
dlv attachto debug the client when it breaks?aykevl commentedon Sep 21, 2024
No, I simply sent the process a SIGABRT when it got stuck and pulled out the stack trace of the right goroutine.
(SIGABRT will print the stack trace of every goroutine that's active).
aykevl commentedon Sep 21, 2024
This is the
AppPlayer.Runstack trace (that I still had in my terminal history):So apparently it's stuck here:
go-librespot/audio/provider.go
Line 110 in 9e41b6c
aykevl commentedon Sep 21, 2024
Going further down the rabbit hole, here is the stack trace for the KeyProvider:
So it's just waiting in the
select. Looks like the response there was just never sent from Spotify, so the request never got something on the response channel?I'm very much out of my depth here, but I hope this gives some ideas how to fix the issue.
fix: timeout audio key requests
devgianlu commentedon Sep 21, 2024
Surely there is potential for a bug in
KeyProviderbecause if the connection breaks while making the request no response is ever sent back and it will just wait forever. I have added a timeout of 15 seconds with 117b929, let's see if that helps with this too.aykevl commentedon Sep 22, 2024
Thanks! I'll be trying this patch, see if it improves anything. I should know whether it helps in a day or so.
aykevl commentedon Sep 22, 2024
The fix appears to be working! When I connected after a few hours I got "authenticated Login5 as (...)" which I guess means the connection was re-established. I'll monitor the daemon some more and will let you know if there's any issue.
I normally run a Spotify daemon (go-librespot or otherwise) 24/7 and use it frequently, so I should easily find issues that only happen after running for a while.
devgianlu commentedon Sep 23, 2024
While the issue with the "deadlock" is fixed, I seem to be still having issues:
All seems good, but the device disappears from Spotify Connect.
aykevl commentedon Sep 24, 2024
Yeah, I'm also still hitting problems. Just slightly different ones.
Here is one:
Here is another:
I'm not exactly what happened the second time, but it seems to have triggered something on Spotify's side. When it automatically restarted the process, it could not authenticate anymore:
I had to reset my password to use Spotify again. Maybe unrelated, but it seems like a weird coincidence.
3 remaining items
devgianlu commentedon Sep 27, 2024
Ah ok, didn't think there were still problems with AP specifically. Perhaps it's better to track AP and Dealer bugs separately.
aykevl commentedon Sep 28, 2024
Maybe when the dealer connection breaks, it also needs to disconnect and reconnect the AP?
I'm going to test this theory now, see if it improves anything.
fix: do not throw away AP receivers on reconnection
devgianlu commentedon Sep 28, 2024
I think I found the culprit for the double AP timeout: when reconnecting the AP would throw away all the registered receivers making the
KeyProviderlisten on a one-ended channel.Should be fixed with 516de68
aykevl commentedon Sep 29, 2024
Yes! I was really close to figuring it out, you found it slightly earlier :)
I noticed that an AES response packet was received, but somehow the timeout still happened. So I was suspecting the AP somehow lost the channel to the KeyProvider, or used the wrong channel or something. The bug you found is certainly consistent with that.
I'll test the patch and let you know whether it fixes the issue for me!
aykevl commentedon Sep 29, 2024
So far holding steady (it would usually have errored out by now).
aykevl commentedon Sep 30, 2024
Still running after 38 hours 💪 even surviving the Spotify outage yesterday (though of course it wasn't usable during the outage). I'd say this bug is fixed.
Notably, the timeout in 117b929 was never triggered during this period. Apparently it managed to reconnect within 15 seconds each time.
fix: timeout audio key requests
fix: do not throw away AP receivers on reconnection
linknum23 commentedon Nov 20, 2024
One of AmpliPi's customers appears to be having this issue with go-librespot_linux_armv6_rpi.tar.gz running on a Pi3 compute module with a similar log
aykevl commentedon Nov 21, 2024
What I did was I sent the process a
SIGABRTwhich causes it to print the stack trace of every goroutine, and look for ones that seem to be blocked. Especially those in a "channel recv" state or similar (where that isn't the intention).Perhaps it's better to create a new issue? Because this issue was already solved a while ago.
devgianlu commentedon Nov 21, 2024
Agree, I thought we eradicated this bug once for all (sigh).
@linknum23 Can you open a new issue? Including the stacktraces would be a real bonus.
fix: timeout audio key requests
fix: do not throw away AP receivers on reconnection