[GH-ISSUE #88] Shannon connection is not re-established on failure

kerem commented

2026-02-28 14:25:02 +03:00

Owner

Originally created by @aykevl on GitHub (Sep 10, 2024).
Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/88

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.

Originally created by @aykevl on GitHub (Sep 10, 2024). Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/88 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.

kerem

2026-02-28 14:25:02 +03:00

closed this issue
added the
bug
label

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 10, 2024):

I have observed this myself too, it was working fine before, I think it's a regression introduced by https://github.com/devgianlu/go-librespot/pull/69. I did not debug this yet because I am not able to reproduce it consistenly, just happens randomly on my device.

@devgianlu commented on GitHub (Sep 10, 2024): I have observed this myself too, it was working fine before, I think it's a regression introduced by https://github.com/devgianlu/go-librespot/pull/69. I did not debug this yet because I am not able to reproduce it consistenly, just happens randomly on my device.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (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).

@aykevl commented on GitHub (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).

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@devgianlu commented on GitHub (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.

@devgianlu commented on GitHub (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.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (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:

github.com/devgianlu/go-librespot@b95e6acdcc/dealer/dealer.go (L134-L139)

The recvLoop meanwhile is stuck here:

goroutine 64 gp=0x40001e2540 m=nil [chan receive, 44 minutes]:
runtime.gopark(0x40029736d8?, 0x40b5b8?, 0x88?, 0xc4?, 0x400048a360?)
        /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x4002973660 sp=0x4002973640 pc=0x4732f8
runtime.chanrecv(0x4000130cb0, 0x400297375e, 0x1)
        /usr/local/go/src/runtime/chan.go:639 +0x414 fp=0x40029736e0 sp=0x4002973660 pc=0x40c894
runtime.chanrecv1(0x4000513800?, 0x0?)
        /usr/local/go/src/runtime/chan.go:489 +0x14 fp=0x4002973710 sp=0x40029736e0 pc=0x40c444
github.com/devgianlu/go-librespot/dealer.(*Dealer).handleRequest(0x400016aa90, 0x400034c990)
        /home/ayke/src/go-librespot/dealer/recv.go:237 +0x404 fp=0x4002973e20 sp=0x4002973710 pc=0x841624
github.com/devgianlu/go-librespot/dealer.(*Dealer).recvLoop(0x400016aa90)
        /home/ayke/src/go-librespot/dealer/dealer.go:201 +0x378 fp=0x4002973fb0 sp=0x4002973e20 pc=0x83fc28
github.com/devgianlu/go-librespot/dealer.(*Dealer).startReceiving.func1.gowrap1()
        /home/ayke/src/go-librespot/dealer/dealer.go:113 +0x28 fp=0x4002973fd0 sp=0x4002973fb0 pc=0x83f458
runtime.goexit({})
        /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4002973fd0 sp=0x4002973fd0 pc=0x47afc4
created by github.com/devgianlu/go-librespot/dealer.(*Dealer).startReceiving.func1 in goroutine 1
        /home/ayke/src/go-librespot/dealer/dealer.go:113 +0x8c

So apparently once the connection breaks it gets stuck in this channel receive operation?

github.com/devgianlu/go-librespot@b95e6acdcc/dealer/recv.go (L236-L237)

I'll add some debugging code to try to figure out why it gets stuck there.

@aykevl commented on GitHub (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: https://github.com/devgianlu/go-librespot/blob/b95e6acdcc266e0b54234c0c98ffd3bd6395f9d1/dealer/dealer.go#L134-L139 The `recvLoop` meanwhile is stuck here: ``` goroutine 64 gp=0x40001e2540 m=nil [chan receive, 44 minutes]: runtime.gopark(0x40029736d8?, 0x40b5b8?, 0x88?, 0xc4?, 0x400048a360?) /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x4002973660 sp=0x4002973640 pc=0x4732f8 runtime.chanrecv(0x4000130cb0, 0x400297375e, 0x1) /usr/local/go/src/runtime/chan.go:639 +0x414 fp=0x40029736e0 sp=0x4002973660 pc=0x40c894 runtime.chanrecv1(0x4000513800?, 0x0?) /usr/local/go/src/runtime/chan.go:489 +0x14 fp=0x4002973710 sp=0x40029736e0 pc=0x40c444 github.com/devgianlu/go-librespot/dealer.(*Dealer).handleRequest(0x400016aa90, 0x400034c990) /home/ayke/src/go-librespot/dealer/recv.go:237 +0x404 fp=0x4002973e20 sp=0x4002973710 pc=0x841624 github.com/devgianlu/go-librespot/dealer.(*Dealer).recvLoop(0x400016aa90) /home/ayke/src/go-librespot/dealer/dealer.go:201 +0x378 fp=0x4002973fb0 sp=0x4002973e20 pc=0x83fc28 github.com/devgianlu/go-librespot/dealer.(*Dealer).startReceiving.func1.gowrap1() /home/ayke/src/go-librespot/dealer/dealer.go:113 +0x28 fp=0x4002973fd0 sp=0x4002973fb0 pc=0x83f458 runtime.goexit({}) /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4002973fd0 sp=0x4002973fd0 pc=0x47afc4 created by github.com/devgianlu/go-librespot/dealer.(*Dealer).startReceiving.func1 in goroutine 1 /home/ayke/src/go-librespot/dealer/dealer.go:113 +0x8c ``` So apparently once the connection breaks it gets stuck in this channel receive operation? https://github.com/devgianlu/go-librespot/blob/b95e6acdcc266e0b54234c0c98ffd3bd6395f9d1/dealer/recv.go#L236-L237 I'll add some debugging code to try to figure out why it gets stuck there.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 21, 2024):

That's interesting, I've been looking at the wrong place for some time. I wonder where AppPlayer.Run is stuck then, since it should always reply to the dealer requests.

@aykevl Are you using dlv attach to debug the client when it breaks?

@devgianlu commented on GitHub (Sep 21, 2024): That's interesting, I've been looking at the wrong place for some time. I wonder where `AppPlayer.Run` is stuck then, since it should always reply to the dealer requests. @aykevl Are you using `dlv attach` to debug the client when it breaks?

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (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 commented on GitHub (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).

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 21, 2024):

This is the AppPlayer.Run stack trace (that I still had in my terminal history):

goroutine 1 gp=0x40000021c0 m=nil [chan receive, 44 minutes]:                                                                                                                                
runtime.gopark(0x4000270678?, 0x40b5b8?, 0x18?, 0x0?, 0x40004894a0?)                                                                                                                         
        /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x4000270600 sp=0x40002705e0 pc=0x4732f8                                                                                              
runtime.chanrecv(0x4000131b20, 0x4000270730, 0x1)                                                                                                                                            
        /usr/local/go/src/runtime/chan.go:639 +0x414 fp=0x4000270680 sp=0x4000270600 pc=0x40c894                                                                                             
runtime.chanrecv1(0x40002706d8?, 0x0?)                                                                                                                                                       
        /usr/local/go/src/runtime/chan.go:489 +0x14 fp=0x40002706b0 sp=0x4000270680 pc=0x40c444                                                                                              
github.com/devgianlu/go-librespot/audio.(*KeyProvider).Request(0x400012ade0, {0x4000010730, 0x10, 0x10}, {0x40002a0ab0, 0x14, 0x18})                                                         
        /home/ayke/src/go-librespot/audio/provider.go:110 +0xa8 fp=0x4000270760 sp=0x40002706b0 pc=0x815b18                                                                                  
github.com/devgianlu/go-librespot/player.(*Player).NewStream(0x4000489b00, {{0x4000366188, 0x5}, {0x4000010730, 0x10, 0x10}}, 0xa0, 0x62df0e)                                                
        /home/ayke/src/go-librespot/player/player.go:375 +0x450 fp=0x4000270a30 sp=0x4000270760 pc=0x831cf0                                                                                  
main.(*AppPlayer).loadCurrentTrack(0x40000d0880, 0x0, 0x1)                                                                                                                                   
        /home/ayke/src/go-librespot/cmd/daemon/controls.go:231 +0x444 fp=0x4000270d90 sp=0x4000270a30 pc=0x8f0104                                                                            
main.(*AppPlayer).handlePlayerCommand(_, {0xc15071d, {0x4000235e60, 0x28}, {{0x4000339418, 0x8}, {0x0, 0x0}, {0x4000420000, 0x5db, ...}, ...}})                                              
        /home/ayke/src/go-librespot/cmd/daemon/player.go:210 +0x1634 fp=0x4000271000 sp=0x4000270d90 pc=0x8f70a4                                                                             
main.(*AppPlayer).handleDealerRequest(_, {0x4000130cb0, {0x4000235e00, 0x24}, {0xc15071d, {0x4000235e60, 0x28}, {{0x4000339418, 0x8}, {0x0, ...}, ...}}})                                    
        /home/ayke/src/go-librespot/cmd/daemon/player.go:346 +0xcc fp=0x4000271250 sp=0x4000271000 pc=0x8f76bc                                                                               
main.(*AppPlayer).Run(0x40000d0880, 0x4000092380)                                                                                                                                            
        /home/ayke/src/go-librespot/cmd/daemon/player.go:530 +0x3e8 fp=0x4000271d00 sp=0x4000271250 pc=0x8f8e48                                                                              
main.(*App).withAppPlayer(0x40000d6230, 0x19?)                                                                                                                                               
        /home/ayke/src/go-librespot/cmd/daemon/main.go:199 +0x3f8 fp=0x4000271de0 sp=0x4000271d00 pc=0x8f3b78                                                                                
main.(*App).withCredentials(0x40000d6230, {0x99a100, 0xf2e0e0})                                                                                                                              
        /home/ayke/src/go-librespot/cmd/daemon/main.go:161 +0x24c fp=0x4000271e80 sp=0x4000271de0 pc=0x8f343c                                                                                
main.(*App).Interactive(...)                                                                                                                                                                 
        /home/ayke/src/go-librespot/cmd/daemon/main.go:137                                                                                                                                   
main.main()                                                                                                                                                                                  
        /home/ayke/src/go-librespot/cmd/daemon/main.go:472 +0x454 fp=0x4000271f40 sp=0x4000271e80 pc=0x8f4f14                                                                                
runtime.main()                                                                                                                                                                               
        /usr/local/go/src/runtime/proc.go:272 +0x288 fp=0x4000271fd0 sp=0x4000271f40 pc=0x43e028                                                                                             
runtime.goexit({})                                                                                                                                                                           
        /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4000271fd0 sp=0x4000271fd0 pc=0x47afc4

So apparently it's stuck here:

github.com/devgianlu/go-librespot@9e41b6cb7d/audio/provider.go (L110)

@aykevl commented on GitHub (Sep 21, 2024): This is the `AppPlayer.Run` stack trace (that I still had in my terminal history): ``` goroutine 1 gp=0x40000021c0 m=nil [chan receive, 44 minutes]: runtime.gopark(0x4000270678?, 0x40b5b8?, 0x18?, 0x0?, 0x40004894a0?) /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x4000270600 sp=0x40002705e0 pc=0x4732f8 runtime.chanrecv(0x4000131b20, 0x4000270730, 0x1) /usr/local/go/src/runtime/chan.go:639 +0x414 fp=0x4000270680 sp=0x4000270600 pc=0x40c894 runtime.chanrecv1(0x40002706d8?, 0x0?) /usr/local/go/src/runtime/chan.go:489 +0x14 fp=0x40002706b0 sp=0x4000270680 pc=0x40c444 github.com/devgianlu/go-librespot/audio.(*KeyProvider).Request(0x400012ade0, {0x4000010730, 0x10, 0x10}, {0x40002a0ab0, 0x14, 0x18}) /home/ayke/src/go-librespot/audio/provider.go:110 +0xa8 fp=0x4000270760 sp=0x40002706b0 pc=0x815b18 github.com/devgianlu/go-librespot/player.(*Player).NewStream(0x4000489b00, {{0x4000366188, 0x5}, {0x4000010730, 0x10, 0x10}}, 0xa0, 0x62df0e) /home/ayke/src/go-librespot/player/player.go:375 +0x450 fp=0x4000270a30 sp=0x4000270760 pc=0x831cf0 main.(*AppPlayer).loadCurrentTrack(0x40000d0880, 0x0, 0x1) /home/ayke/src/go-librespot/cmd/daemon/controls.go:231 +0x444 fp=0x4000270d90 sp=0x4000270a30 pc=0x8f0104 main.(*AppPlayer).handlePlayerCommand(_, {0xc15071d, {0x4000235e60, 0x28}, {{0x4000339418, 0x8}, {0x0, 0x0}, {0x4000420000, 0x5db, ...}, ...}}) /home/ayke/src/go-librespot/cmd/daemon/player.go:210 +0x1634 fp=0x4000271000 sp=0x4000270d90 pc=0x8f70a4 main.(*AppPlayer).handleDealerRequest(_, {0x4000130cb0, {0x4000235e00, 0x24}, {0xc15071d, {0x4000235e60, 0x28}, {{0x4000339418, 0x8}, {0x0, ...}, ...}}}) /home/ayke/src/go-librespot/cmd/daemon/player.go:346 +0xcc fp=0x4000271250 sp=0x4000271000 pc=0x8f76bc main.(*AppPlayer).Run(0x40000d0880, 0x4000092380) /home/ayke/src/go-librespot/cmd/daemon/player.go:530 +0x3e8 fp=0x4000271d00 sp=0x4000271250 pc=0x8f8e48 main.(*App).withAppPlayer(0x40000d6230, 0x19?) /home/ayke/src/go-librespot/cmd/daemon/main.go:199 +0x3f8 fp=0x4000271de0 sp=0x4000271d00 pc=0x8f3b78 main.(*App).withCredentials(0x40000d6230, {0x99a100, 0xf2e0e0}) /home/ayke/src/go-librespot/cmd/daemon/main.go:161 +0x24c fp=0x4000271e80 sp=0x4000271de0 pc=0x8f343c main.(*App).Interactive(...) /home/ayke/src/go-librespot/cmd/daemon/main.go:137 main.main() /home/ayke/src/go-librespot/cmd/daemon/main.go:472 +0x454 fp=0x4000271f40 sp=0x4000271e80 pc=0x8f4f14 runtime.main() /usr/local/go/src/runtime/proc.go:272 +0x288 fp=0x4000271fd0 sp=0x4000271f40 pc=0x43e028 runtime.goexit({}) /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4000271fd0 sp=0x4000271fd0 pc=0x47afc4 ``` So apparently it's stuck here: https://github.com/devgianlu/go-librespot/blob/9e41b6cb7d2aaa06cd13b925bf0c27ba5837562a/audio/provider.go#L110

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 21, 2024):

Going further down the rabbit hole, here is the stack trace for the KeyProvider:

goroutine 33 gp=0x4000268000 m=nil [select, 44 minutes]:                                                                                                                                     
runtime.gopark(0x4000076c10?, 0x3?, 0x16?, 0x0?, 0x4000076b4e?)                                                                                                                              
        /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x40000769d0 sp=0x40000769b0 pc=0x4732f8                                                                                              
runtime.selectgo(0x4000076c10, 0x4000076b48, 0xa5f324?, 0x0, 0x4000076f80?, 0x1)                                                                                                             
        /usr/local/go/src/runtime/select.go:335 +0x67c fp=0x4000076b00 sp=0x40000769d0 pc=0x4512bc                                                                                           
github.com/devgianlu/go-librespot/audio.(*KeyProvider).recvLoop(0x400012ade0)                                                                                                                
        /home/ayke/src/go-librespot/audio/provider.go:53 +0x110 fp=0x4000076fb0 sp=0x4000076b00 pc=0x815280                                                                                  
github.com/devgianlu/go-librespot/audio.(*KeyProvider).startReceiving.func1.gowrap1()                                                                                                        
        /home/ayke/src/go-librespot/audio/provider.go:43 +0x28 fp=0x4000076fd0 sp=0x4000076fb0 pc=0x815138                                                                                   
runtime.goexit({})                                                                                                                                                                           
        /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4000076fd0 sp=0x4000076fd0 pc=0x47afc4                                                                                          
created by github.com/devgianlu/go-librespot/audio.(*KeyProvider).startReceiving.func1 in goroutine 1                                                                                        
        /home/ayke/src/go-librespot/audio/provider.go:43 +0x60

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.

@aykevl commented on GitHub (Sep 21, 2024): Going further down the rabbit hole, here is the stack trace for the KeyProvider: ``` goroutine 33 gp=0x4000268000 m=nil [select, 44 minutes]: runtime.gopark(0x4000076c10?, 0x3?, 0x16?, 0x0?, 0x4000076b4e?) /usr/local/go/src/runtime/proc.go:424 +0xc8 fp=0x40000769d0 sp=0x40000769b0 pc=0x4732f8 runtime.selectgo(0x4000076c10, 0x4000076b48, 0xa5f324?, 0x0, 0x4000076f80?, 0x1) /usr/local/go/src/runtime/select.go:335 +0x67c fp=0x4000076b00 sp=0x40000769d0 pc=0x4512bc github.com/devgianlu/go-librespot/audio.(*KeyProvider).recvLoop(0x400012ade0) /home/ayke/src/go-librespot/audio/provider.go:53 +0x110 fp=0x4000076fb0 sp=0x4000076b00 pc=0x815280 github.com/devgianlu/go-librespot/audio.(*KeyProvider).startReceiving.func1.gowrap1() /home/ayke/src/go-librespot/audio/provider.go:43 +0x28 fp=0x4000076fd0 sp=0x4000076fb0 pc=0x815138 runtime.goexit({}) /usr/local/go/src/runtime/asm_arm64.s:1223 +0x4 fp=0x4000076fd0 sp=0x4000076fd0 pc=0x47afc4 created by github.com/devgianlu/go-librespot/audio.(*KeyProvider).startReceiving.func1 in goroutine 1 /home/ayke/src/go-librespot/audio/provider.go:43 +0x60 ``` 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.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 21, 2024):

Surely there is potential for a bug in KeyProvider because 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 117b929858, let's see if that helps with this too.

@devgianlu commented on GitHub (Sep 21, 2024): Surely there is potential for a bug in `KeyProvider` because 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 117b929858ec3723496314840e85e14db1b2e892, let's see if that helps with this too.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (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 commented on GitHub (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.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (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.

@aykevl commented on GitHub (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.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 23, 2024):

While the issue with the "deadlock" is fixed, I seem to be still having issues:

Sep 23 09:53:21 volofritz go-librespot[14939]: time="2024-09-23T09:53:21+02:00" level=debug msg="handling transfer player command from 1fdaedb840e99078c8ef663e0be67d6c2f319121"
Sep 23 09:53:21 volofritz go-librespot[14939]: time="2024-09-23T09:53:21+02:00" level=debug msg="renewing login5 access token"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=info msg="authenticated Login5 as 11145089019"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="resolved context of track" uri="spotify:user:11145089019:collection"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=trace msg="fetched new page 0 with 676 items (list: 676)" uri="spotify:user:11145089019:collection"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="shuffled context with seed 899671373019070007 (len: 676, keep: 390)"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="loading track (paused: false, position: 7201ms)" uri="spotify:track:4kbj5MwxO1bq9wjT5g9HaA"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=trace msg="emitting websocket event: will_play"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (142b958aecdc0ebc66b1ee2c8d6f6166d487088b)" uri="spotify:track:4kbj5MwxO1bq9wjT5g9HaA"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="requested aes key for file 142b958aecdc0ebc66b1ee2c8d6f6166d487088b, gid: 4kbj5MwxO1bq9wjT5g9HaA"
Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="skipping packet PacketTypeAesKey, len: 20"
Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:4kbj5MwxO1bq9wjT5g9HaA: failed retrieving audio key: request timed out"
Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=debug msg="put connect state inactive"
Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=trace msg="emitting websocket event: inactive"
Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=trace msg="emitting websocket event: stopped"
Sep 23 09:53:43 volofritz go-librespot[14939]: time="2024-09-23T09:53:43+02:00" level=trace msg="sent dealer ping"
Sep 23 09:53:43 volofritz go-librespot[14939]: time="2024-09-23T09:53:43+02:00" level=trace msg="received dealer pong"
Sep 23 09:54:11 volofritz go-librespot[14939]: time="2024-09-23T09:54:11+02:00" level=trace msg="received accesspoint ping"
Sep 23 09:54:11 volofritz go-librespot[14939]: time="2024-09-23T09:54:11+02:00" level=trace msg="received accesspoint pong ack"
Sep 23 09:54:13 volofritz go-librespot[14939]: time="2024-09-23T09:54:13+02:00" level=trace msg="sent dealer ping"
Sep 23 09:54:13 volofritz go-librespot[14939]: time="2024-09-23T09:54:13+02:00" level=trace msg="received dealer pong"

All seems good, but the device disappears from Spotify Connect.

@devgianlu commented on GitHub (Sep 23, 2024): While the issue with the "deadlock" is fixed, I seem to be still having issues: ``` Sep 23 09:53:21 volofritz go-librespot[14939]: time="2024-09-23T09:53:21+02:00" level=debug msg="handling transfer player command from 1fdaedb840e99078c8ef663e0be67d6c2f319121" Sep 23 09:53:21 volofritz go-librespot[14939]: time="2024-09-23T09:53:21+02:00" level=debug msg="renewing login5 access token" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=info msg="authenticated Login5 as 11145089019" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="resolved context of track" uri="spotify:user:11145089019:collection" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=trace msg="fetched new page 0 with 676 items (list: 676)" uri="spotify:user:11145089019:collection" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="shuffled context with seed 899671373019070007 (len: 676, keep: 390)" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="loading track (paused: false, position: 7201ms)" uri="spotify:track:4kbj5MwxO1bq9wjT5g9HaA" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=trace msg="emitting websocket event: will_play" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (142b958aecdc0ebc66b1ee2c8d6f6166d487088b)" uri="spotify:track:4kbj5MwxO1bq9wjT5g9HaA" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="requested aes key for file 142b958aecdc0ebc66b1ee2c8d6f6166d487088b, gid: 4kbj5MwxO1bq9wjT5g9HaA" Sep 23 09:53:22 volofritz go-librespot[14939]: time="2024-09-23T09:53:22+02:00" level=debug msg="skipping packet PacketTypeAesKey, len: 20" Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:4kbj5MwxO1bq9wjT5g9HaA: failed retrieving audio key: request timed out" Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=debug msg="put connect state inactive" Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=trace msg="emitting websocket event: inactive" Sep 23 09:53:37 volofritz go-librespot[14939]: time="2024-09-23T09:53:37+02:00" level=trace msg="emitting websocket event: stopped" Sep 23 09:53:43 volofritz go-librespot[14939]: time="2024-09-23T09:53:43+02:00" level=trace msg="sent dealer ping" Sep 23 09:53:43 volofritz go-librespot[14939]: time="2024-09-23T09:53:43+02:00" level=trace msg="received dealer pong" Sep 23 09:54:11 volofritz go-librespot[14939]: time="2024-09-23T09:54:11+02:00" level=trace msg="received accesspoint ping" Sep 23 09:54:11 volofritz go-librespot[14939]: time="2024-09-23T09:54:11+02:00" level=trace msg="received accesspoint pong ack" Sep 23 09:54:13 volofritz go-librespot[14939]: time="2024-09-23T09:54:13+02:00" level=trace msg="sent dealer ping" Sep 23 09:54:13 volofritz go-librespot[14939]: time="2024-09-23T09:54:13+02:00" level=trace msg="received dealer pong" ``` All seems good, but the device disappears from Spotify Connect.

kerem commented

2026-02-28 14:25:03 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 24, 2024):

Yeah, I'm also still hitting problems. Just slightly different ones.

Here is one:

ERRO[28321] did not receive last pong ack from accesspoint, 120s passed                                                                                                                                                                                                                   
ERRO[28321] failed receiving packet                       error="failed reading packet header: read tcp 10.65.42.112:51710->34.158.1.133:4070: use of closed network connection"                                                                                                          
INFO[28322] authenticated AP as [...]                                                                                                                                                                                                                                 
WARN[28512] failed prefetching track stream               error="failed retrieving audio key: request timed out" uri="spotify:track:5D1O32P2TcnIUVnGemrPDz"                                                                                                                               
ERRO[28540] failed advancing to next track                error="failed loading current track (advance to spotify:track:5D1O32P2TcnIUVnGemrPDz): failed creating stream for spotify:track:5D1O32P2TcnIUVnGemrPDz: failed retrieving audio key: request timed out"                         
WARN[30924] failed handling dealer request                error="no primary stream"                                                                                                                                                                                                       
WARN[30928] failed handling dealer request                error="no primary stream"                                                                                                                                                                                                       
WARN[30947] failed handling dealer request                error="failed loading current track (load context): failed creating stream for spotify:track:6y0i3SNahBx0E8jU8RsieT: failed retrieving audio key: request timed out"

Here is another:

INFO[6925] loaded track "Distant Oceans" (paused: false, position: 0ms, duration: 138666ms, prefetched: true)  uri="spotify:track:4TbaG2d0oHVSL5WWHr3paT"                                                                                                                                 
INFO[7578] authenticated Login5 as [...]                                                                                                                                                                                                                              
ERRO[8251] failed receiving dealer message               error="failed to get reader: received close frame: status = StatusNormalClosure and reason = \"Request disconnect\""                                                                                                             
ERRO[8252] failed receiving packet                       error="failed reading packet header: EOF"                                                                                                                                                                                        
ERRO[8281] did not receive last pong ack from accesspoint, 120s passed                                                                                                                                                                                                                    
ERRO[8401] did not receive last pong ack from accesspoint, 240s passed                                                                                                                                                                                                                    
ERRO[8521] did not receive last pong ack from accesspoint, 360s passed                                                                                                                                                                                                                    
ERRO[8641] did not receive last pong ack from accesspoint, 480s passed                                                                                                                                                                                                                    
ERRO[8761] did not receive last pong ack from accesspoint, 600s passed                                                                                                                                                                                                                    
ERRO[8881] did not receive last pong ack from accesspoint, 720s passed                                                                                                                                                                                                                    
ERRO[9001] did not receive last pong ack from accesspoint, 840s passed                                                                                                                                                                                                                    
ERRO[9121] did not receive last pong ack from accesspoint, 960s passed                                                                                                                                                                                                                    
ERRO[9130] failed reconnecting accesspoint, bye bye      error="failed authenticating: failed login: BadCredentials"
exit status 1

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:

INFO[0000] generated new device id: 489d95c35452c8e53b04d3f40fe71fc790c70ba6                                                                                                                                                                                                              
FATA[0001] failed running with interactive auth          error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"

I had to reset my password to use Spotify again. Maybe unrelated, but it seems like a weird coincidence.

@aykevl commented on GitHub (Sep 24, 2024): Yeah, I'm also still hitting problems. Just slightly different ones. Here is one: ``` ERRO[28321] did not receive last pong ack from accesspoint, 120s passed ERRO[28321] failed receiving packet error="failed reading packet header: read tcp 10.65.42.112:51710->34.158.1.133:4070: use of closed network connection" INFO[28322] authenticated AP as [...] WARN[28512] failed prefetching track stream error="failed retrieving audio key: request timed out" uri="spotify:track:5D1O32P2TcnIUVnGemrPDz" ERRO[28540] failed advancing to next track error="failed loading current track (advance to spotify:track:5D1O32P2TcnIUVnGemrPDz): failed creating stream for spotify:track:5D1O32P2TcnIUVnGemrPDz: failed retrieving audio key: request timed out" WARN[30924] failed handling dealer request error="no primary stream" WARN[30928] failed handling dealer request error="no primary stream" WARN[30947] failed handling dealer request error="failed loading current track (load context): failed creating stream for spotify:track:6y0i3SNahBx0E8jU8RsieT: failed retrieving audio key: request timed out" ``` Here is another: ``` INFO[6925] loaded track "Distant Oceans" (paused: false, position: 0ms, duration: 138666ms, prefetched: true) uri="spotify:track:4TbaG2d0oHVSL5WWHr3paT" INFO[7578] authenticated Login5 as [...] ERRO[8251] failed receiving dealer message error="failed to get reader: received close frame: status = StatusNormalClosure and reason = \"Request disconnect\"" ERRO[8252] failed receiving packet error="failed reading packet header: EOF" ERRO[8281] did not receive last pong ack from accesspoint, 120s passed ERRO[8401] did not receive last pong ack from accesspoint, 240s passed ERRO[8521] did not receive last pong ack from accesspoint, 360s passed ERRO[8641] did not receive last pong ack from accesspoint, 480s passed ERRO[8761] did not receive last pong ack from accesspoint, 600s passed ERRO[8881] did not receive last pong ack from accesspoint, 720s passed ERRO[9001] did not receive last pong ack from accesspoint, 840s passed ERRO[9121] did not receive last pong ack from accesspoint, 960s passed ERRO[9130] failed reconnecting accesspoint, bye bye error="failed authenticating: failed login: BadCredentials" exit status 1 ``` 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: ``` INFO[0000] generated new device id: 489d95c35452c8e53b04d3f40fe71fc790c70ba6 FATA[0001] failed running with interactive auth error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" ``` I had to reset my password to use Spotify again. Maybe unrelated, but it seems like a weird coincidence.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 25, 2024):

Somewhat unrelated, but I got this error in my log at some point and found it interesting:

ERRO[40067] failed receiving dealer message               error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"Service is going to be redeployed\""

go-librespot was already kinda stuck due to previous errors so I don't know whether it would normally have recovered from this.

@aykevl commented on GitHub (Sep 25, 2024): Somewhat unrelated, but I got this error in my log at some point and found it interesting: ``` ERRO[40067] failed receiving dealer message error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"Service is going to be redeployed\"" ``` go-librespot was already kinda stuck due to previous errors so I don't know whether it would normally have recovered from this.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 26, 2024):

I had to reset my password to use Spotify again

I know one person that had to it, but in 5 years of messing with Spotify stuff I don't think it ever happened to me. Strange.

Anyway, The deamon is a lot more stable for me. Do you mind if we close this and create new issues dedicated to each specific problem? @aykevl

@devgianlu commented on GitHub (Sep 26, 2024): > I had to reset my password to use Spotify again I know one person that had to it, but in 5 years of messing with Spotify stuff I don't think it ever happened to me. Strange. Anyway, The deamon is a lot more stable for me. Do you mind if we close this and create new issues dedicated to each specific problem? @aykevl

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 26, 2024):

I know one person that had to it, but in 5 years of messing with Spotify stuff I don't think it ever happened to me. Strange.

🤷‍♀️ As long as it doesn't keep happening.

Anyway, The deamon is a lot more stable for me. Do you mind if we close this and create new issues dedicated to each specific problem?

It doesn't seem fixed to me? Or did I miss something?
github.com/devgianlu/go-librespot@117b929858 changes things, but doesn't seem to fix the issue. The error message is different but the Spotify Connect connection still breaks. I suspect the bug isn't fully fixed yet.

I also made a quick patch where I retried to send the message on timeout but the 2nd also timed out. So whatever the problem is, it doesn't fix itself after the timeout.

@aykevl commented on GitHub (Sep 26, 2024): > I know one person that had to it, but in 5 years of messing with Spotify stuff I don't think it ever happened to me. Strange. 🤷‍♀️ As long as it doesn't keep happening. > Anyway, The deamon is a lot more stable for me. Do you mind if we close this and create new issues dedicated to each specific problem? It doesn't seem fixed to me? Or did I miss something? https://github.com/devgianlu/go-librespot/commit/117b929858ec3723496314840e85e14db1b2e892 changes things, but doesn't seem to fix the issue. The error message is different but the Spotify Connect connection still breaks. I suspect the bug isn't fully fixed yet. I also made a quick patch where I retried to send the message on timeout but the 2nd also timed out. So whatever the problem is, it doesn't fix itself after the timeout.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@devgianlu commented on GitHub (Sep 27, 2024):

I also made a quick patch where I retried to send the message on timeout but the 2nd also timed out. So whatever the problem is, it doesn't fix itself after the timeout.

Ah ok, didn't think there were still problems with AP specifically. Perhaps it's better to track AP and Dealer bugs separately.

@devgianlu commented on GitHub (Sep 27, 2024): > I also made a quick patch where I retried to send the message on timeout but the 2nd also timed out. So whatever the problem is, it doesn't fix itself after the timeout. Ah ok, didn't think there were still problems with AP specifically. Perhaps it's better to track AP and Dealer bugs separately.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (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.

@aykevl commented on GitHub (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.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@devgianlu commented on GitHub (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 KeyProvider listen on a one-ended channel.

Should be fixed with 516de6899c

@devgianlu commented on GitHub (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 `KeyProvider` listen on a one-ended channel. Should be fixed with 516de6899c9d9fdce2d71d3456d3ef6ebac230a3

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (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 commented on GitHub (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!

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (Sep 29, 2024):

So far holding steady (it would usually have errored out by now).

@aykevl commented on GitHub (Sep 29, 2024): So far holding steady (it would usually have errored out by now).

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (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 github.com/devgianlu/go-librespot@117b929858 was never triggered during this period. Apparently it managed to reconnect within 15 seconds each time.

@aykevl commented on GitHub (Sep 30, 2024): Still running after 38 hours :muscle: even surviving the [Spotify outage](https://x.com/SpotifyStatus/status/1840424945748160733) yesterday (though of course it wasn't usable during the outage). I'd say this bug is fixed. Notably, the timeout in https://github.com/devgianlu/go-librespot/commit/117b929858ec3723496314840e85e14db1b2e892 was never triggered during this period. Apparently it managed to reconnect within 15 seconds each time.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@linknum23 commented on GitHub (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

time="2024-11-19T17:31:24-07:00" level=info msg="running go-librespot 0.1.2"
time="2024-11-19T17:31:24-07:00" level=info msg="generated new device id: 4907a0325a22d241f6dbc510fe718603dad8c512"
time="2024-11-19T17:31:24-07:00" level=info msg="api server listening on 127.0.0.1:3679"
time="2024-11-19T17:31:37-07:00" level=info msg="zeroconf server listening on port 39801"
time="2024-11-19T17:41:10-07:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused"
time="2024-11-19T17:41:10-07:00" level=info msg="authenticated AP as matchmee"
time="2024-11-19T17:41:11-07:00" level=info msg="authenticated Login5 as matchmee"
time="2024-11-19T17:41:11-07:00" level=info msg="accepted zeroconf user matchmee from iPhone"
time="2024-11-19T17:42:41-07:00" level=error msg="did not receive last pong from dealer, 60s passed"
time="2024-11-19T17:43:11-07:00" level=error msg="did not receive last pong from dealer, 90s passed"
time="2024-11-19T17:43:41-07:00" level=error msg="did not receive last pong from dealer, 120s passed"
time="2024-11-19T17:44:11-07:00" level=error msg="did not receive last pong from dealer, 150s passed"
time="2024-11-19T17:44:41-07:00" level=error msg="did not receive last pong from dealer, 180s passed"
time="2024-11-19T17:45:11-07:00" level=error msg="did not receive last pong from dealer, 210s passed"
time="2024-11-19T17:45:41-07:00" level=error msg="did not receive last pong from dealer, 240s passed"
...

Is there any additional information we can get to debug this further?

@linknum23 commented on GitHub (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 ``` time="2024-11-19T17:31:24-07:00" level=info msg="running go-librespot 0.1.2" time="2024-11-19T17:31:24-07:00" level=info msg="generated new device id: 4907a0325a22d241f6dbc510fe718603dad8c512" time="2024-11-19T17:31:24-07:00" level=info msg="api server listening on 127.0.0.1:3679" time="2024-11-19T17:31:37-07:00" level=info msg="zeroconf server listening on port 39801" time="2024-11-19T17:41:10-07:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" time="2024-11-19T17:41:10-07:00" level=info msg="authenticated AP as matchmee" time="2024-11-19T17:41:11-07:00" level=info msg="authenticated Login5 as matchmee" time="2024-11-19T17:41:11-07:00" level=info msg="accepted zeroconf user matchmee from iPhone" time="2024-11-19T17:42:41-07:00" level=error msg="did not receive last pong from dealer, 60s passed" time="2024-11-19T17:43:11-07:00" level=error msg="did not receive last pong from dealer, 90s passed" time="2024-11-19T17:43:41-07:00" level=error msg="did not receive last pong from dealer, 120s passed" time="2024-11-19T17:44:11-07:00" level=error msg="did not receive last pong from dealer, 150s passed" time="2024-11-19T17:44:41-07:00" level=error msg="did not receive last pong from dealer, 180s passed" time="2024-11-19T17:45:11-07:00" level=error msg="did not receive last pong from dealer, 210s passed" time="2024-11-19T17:45:41-07:00" level=error msg="did not receive last pong from dealer, 240s passed" ... Is there any additional information we can get to debug this further?

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@aykevl commented on GitHub (Nov 21, 2024):

What I did was I sent the process a SIGABRT which 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.

@aykevl commented on GitHub (Nov 21, 2024): What I did was I sent the process a `SIGABRT` which 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.

kerem commented

2026-02-28 14:25:04 +03:00

Author

Owner

@devgianlu commented on GitHub (Nov 21, 2024):

Perhaps it's better to create a new issue? Because this issue was already solved a while ago.

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.

@devgianlu commented on GitHub (Nov 21, 2024): > Perhaps it's better to create a new issue? Because this issue was already solved a while ago. 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.

Rows
Columns

[GH-ISSUE #88] Shannon connection is not re-established on failure #62