Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Crash on handlePlayerCommand() #150

Closed
2opremio opened this issue Nov 21, 2024 · 16 comments
Closed

Crash on handlePlayerCommand() #150

2opremio opened this issue Nov 21, 2024 · 16 comments
Labels
bug Something isn't working

Comments

@2opremio
Copy link
Contributor

2opremio commented Nov 21, 2024

Using today's master:

Nov 21 15:59:51 duchamp systemd[1]: Started go-librespot.service - Yet another open-source Spotify Connect compatible client, written in Go.
Nov 21 15:59:51 duchamp go-librespot[10047]: time="2024-11-21T15:59:51Z" level=info msg="running go-librespot 0.0.0"
Nov 21 15:59:51 duchamp go-librespot[10047]: time="2024-11-21T15:59:51Z" level=info msg="api server listening on 127.0.0.1:3678"
Nov 21 15:59:51 duchamp go-librespot[10047]: time="2024-11-21T15:59:51Z" level=info msg="zeroconf server listening on port 41787"
Nov 21 15:59:51 duchamp go-librespot[10047]: time="2024-11-21T15:59:51Z" level=info msg="loading previously persisted zeroconf credentials" username=aacosta
Nov 21 15:59:52 duchamp go-librespot[10047]: time="2024-11-21T15:59:52Z" level=info msg="authenticated AP as redacted"
Nov 21 15:59:52 duchamp go-librespot[10047]: time="2024-11-21T15:59:52Z" level=info msg="authenticated Login5 as redacted"
Nov 21 15:59:59 duchamp go-librespot[10047]: panic: runtime error: invalid memory address or nil pointer dereference
Nov 21 15:59:59 duchamp go-librespot[10047]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x14 pc=0x61e0cc]
Nov 21 15:59:59 duchamp go-librespot[10047]: goroutine 62 [running]:
Nov 21 15:59:59 duchamp go-librespot[10047]: main.(*AppPlayer).handlePlayerCommand(0x10ace10, {0x80a474, 0xc2ad60}, {0x4f73aa45, {0x122c330, 0x27}, {{0x1011c80, 0x8}, {0x0, 0x0}, ...}})
Nov 21 15:59:59 duchamp go-librespot[10047]:         /src/cmd/daemon/player.go:152 +0xe94
Nov 21 15:59:59 duchamp go-librespot[10047]: main.(*AppPlayer).handleDealerRequest(0x10ace10, {0x80a474, 0xc2ad60}, {0x11939c0, {0x117d740, 0x24}, {0x4f73aa45, {0x122c330, 0x27}, {{0x1011c80, ...}, ...}}})
Nov 21 15:59:59 duchamp go-librespot[10047]:         /src/cmd/daemon/player.go:347 +0xf4
Nov 21 15:59:59 duchamp go-librespot[10047]: main.(*AppPlayer).Run(0x10ace10, {0x80a474, 0xc2ad60}, 0x1090b00)
Nov 21 15:59:59 duchamp go-librespot[10047]:         /src/cmd/daemon/player.go:573 +0x4bc
Nov 21 15:59:59 duchamp go-librespot[10047]: created by main.(*App).withAppPlayer in goroutine 1
Nov 21 15:59:59 duchamp go-librespot[10047]:         /src/cmd/daemon/main.go:232 +0x37c
Nov 21 15:59:59 duchamp systemd[1]: go-librespot.service: Main process exited, code=exited, status=2/INVALIDARGUMENT

This started happening systematically a couple of days ago.

This seems to be the culprit:

		p.state.lastTransferTimestamp = transferState.Playback.Timestamp

Probably a nil pointer? I haven't had time to take a look into it and won't until next week.

@szygmunt
Copy link

Offtop: could you share your go-libtespot.service file?

@2opremio
Copy link
Contributor Author

[Unit]
Description=Yet another open-source Spotify Connect compatible client, written in Go
Documentation=https://github.com/devgianlu/go-librespot
Wants=sound.target
After=sound.target
Wants=network-online.target
After=network-online.target

[Service]
ExecStart=/home/fons/go-librespot
User=fons
Restart=always
RestartSec=5

[Install]
WantedBy=default.target

@devgianlu devgianlu added the bug Something isn't working label Nov 21, 2024
@devgianlu
Copy link
Owner

p.state cannot be nil because it is initialized before handlePlayerCommand even has a chance to be called, transferState is not a pointer, this leaves out only transferState.Playback to be nil. Makes very little sense.

@2opremio How are you transfering playback to go-librespot?

@2opremio
Copy link
Contributor Author

2opremio commented Nov 21, 2024

With https://github.com/zmb3/spotify , using my personal account. It has been working flawlessly for years with spotifyd (and up until now, for a couple of weeks, with go-librespot).

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

After adding the following patch:

diff --git a/cmd/daemon/player.go b/cmd/daemon/player.go
index 1754206..efbf41f 100644
--- a/cmd/daemon/player.go
+++ b/cmd/daemon/player.go
@@ -149,6 +149,9 @@ func (p *AppPlayer) handlePlayerCommand(ctx context.Context, req dealer.RequestP
                if err := proto.Unmarshal(req.Command.Data, &transferState); err != nil {
                        return fmt.Errorf("failed unmarshalling TransferState: %w", err)
                }
+               fmt.Printf("request: %#v\n", req)
+               fmt.Printf("command data: %#v\n", req.Command.Data)
+               fmt.Printf("playback is nil: %t\n", transferState.Playback == nil)
                p.state.lastTransferTimestamp = transferState.Playback.Timestamp
 
                ctxTracks, err := tracks.NewTrackListFromContext(ctx, p.sess.Spclient(), transferState.CurrentSession.Context)

I can confirm that the playback is nil (or incorrectly deserialized to nil)

Here is are the logs with the patch applied:

Dec 04 15:16:37 duchamp go-librespot[733]: request: dealer.RequestPayload{MessageId:0x123ea1c1, SentByDeviceId:"webapi-cfe923b2d660439caf2b557b21f31221", Command:struct { Endpoint string "json:\"endpoint\""; SessionId string "json:\"session_id\""; Data []uint8 "json:\"data\""; Value interface {} "json:\"value\""; Position int64 "json:\"position\""; Relative string "json:\"relative\""; Context *connectstate.Context "json:\"context\""; PlayOrigin *connectstate.PlayOrigin "json:\"play_origin\""; Track *connectstate.ContextTrack "json:\"track\""; PrevTracks []*connectstate.ContextTrack "json:\"prev_tracks\""; NextTracks []*connectstate.ContextTrack "json:\"next_tracks\""; RepeatingTrack *bool "json:\"repeating_track\""; RepeatingContext *bool "json:\"repeating_context\""; ShufflingContext *bool "json:\"shuffling_context\""; LoggingParams struct { CommandInitiatedTime int64 "json:\"command_initiated_time\""; PageInstanceIds []string "json:\"page_instance_ids\""; InteractionIds []string "json:\"interaction_ids\""; DeviceIdentifier string "json:\"device_identifier\"" } "json:\"logging_params\""; Options struct { RestorePaused string "json:\"restore_paused\""; RestorePosition string "json:\"restore_position\""; RestoreTrack string "json:\"restore_track\""; AlwaysPlaySomething bool "json:\"always_play_something\""; AllowSeeking bool "json:\"allow_seeking\""; SkipTo struct { TrackUid string "json:\"track_uid\""; TrackUri string "json:\"track_uri\""; TrackIndex int "json:\"track_index\"" } "json:\"skip_to\""; InitiallyPaused bool "json:\"initially_paused\""; SystemInitiated bool "json:\"system_initiated\""; PlayerOptionsOverride *connectstate.ContextPlayerOptionOverrides "json:\"player_options_override\""; Suppressions *connectstate.Suppressions "json:\"suppressions\""; PrefetchLevel string "json:\"prefetch_level\""; AudioStream string "json:\"audio_stream\""; SessionId string "json:\"session_id\""; License string "json:\"license\"" } "json:\"options\""; PlayOptions struct { OverrideRestrictions bool "json:\"override_restrictions\""; OnlyForLocalDevice bool "json:\"only_for_local_device\""; SystemInitiated bool "json:\"system_initiated\""; Reason string "json:\"reason\""; Operation string "json:\"operation\""; Trigger string "json:\"trigger\"" } "json:\"play_options\""; FromDeviceIdentifier string "json:\"from_device_identifier\"" }{Endpoint:"transfer", SessionId:"", Data:[]uint8{}, Value:interface {}(nil), Position:0, Relative:"", Context:(*connectstate.Context)(nil), PlayOrigin:(*connectstate.PlayOrigin)(nil), Track:(*connectstate.ContextTrack)(nil), PrevTracks:[]*connectstate.ContextTrack(nil), NextTracks:[]*connectstate.ContextTrack(nil), RepeatingTrack:(*bool)(nil), RepeatingContext:(*bool)(nil), ShufflingContext:(*bool)(nil), LoggingParams:struct { CommandInitiatedTime int64 "json:\"command_initiated_time\""; PageInstanceIds []string "json:\"page_instance_ids\""; InteractionIds []string "json:\"interaction_ids\""; DeviceIdentifier string "json:\"device_identifier\"" }{CommandInitiatedTime:0, PageInstanceIds:[]string(nil), InteractionIds:[]string(nil), DeviceIdentifier:""}, Options:struct { RestorePaused string "json:\"restore_paused\""; RestorePosition string "json:\"restore_position\""; RestoreTrack string "json:\"restore_track\""; AlwaysPlaySomething bool "json:\"always_play_something\""; AllowSeeking bool "json:\"allow_seeking\""; SkipTo struct { TrackUid string "json:\"track_uid\""; TrackUri string "json:\"track_uri\""; TrackIndex int "json:\"track_index\"" } "json:\"skip_to\""; InitiallyPaused bool "json:\"initially_paused\""; SystemInitiated bool "json:\"system_initiated\""; PlayerOptionsOverride *connectstate.ContextPlayerOptionOverrides "json:\"player_options_override\""; Suppressions *connectstate.Suppressions "json:\"suppressions\""; PrefetchLevel string "json:\"prefetch_level\""; AudioStream string "json:\"audio_stream\""; SessionId string "json:\"session_id\""; License string "json:\"license\"" }{RestorePaused:"resume", RestorePosition:"last_known", RestoreTrack:"always_play_something", AlwaysPlaySomething:false, AllowSeeking:false, SkipTo:struct { TrackUid string "json:\"track_uid\""; TrackUri string "json:\"track_uri\""; TrackIndex int "json:\"track_index\"" }{TrackUid:"", TrackUri:"", TrackIndex:0}, InitiallyPaused:false, SystemInitiated:false, PlayerOptionsOverride:(*connectstate.ContextPlayerOptionOverrides)(nil), Suppressions:(*connectstate.Suppressions)(nil), PrefetchLevel:"", AudioStream:"", SessionId:"", License:""}, PlayOptions:struct { OverrideRestrictions bool "json:\"override_restrictions\""; OnlyForLocalDevice bool "json:\"only_for_local_device\""; SystemInitiated bool "json:\"system_initiated\""; Reason string "json:\"reason\""; Operation string "json:\"operation\""; Trigger string "json:\"trigger\"" }{OverrideRestrictions:false, OnlyForLocalDevice:false, SystemInitiated:false, Reason:"", Operation:"", Trigger:""}, FromDeviceIdentifier:"webapi-cfe923b2d660439caf2b557b21f31221"}}
Dec 04 15:16:37 duchamp go-librespot[733]: command data: []byte{}
Dec 04 15:16:37 duchamp go-librespot[733]: playback is nil: true
Dec 04 15:16:37 duchamp go-librespot[733]: panic: runtime error: invalid memory address or nil pointer dereference
Dec 04 15:16:37 duchamp go-librespot[733]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x14 pc=0x61e224]
Dec 04 15:16:37 duchamp go-librespot[733]: goroutine 12 [running]:
Dec 04 15:16:37 duchamp go-librespot[733]: main.(*AppPlayer).handlePlayerCommand(0x10ac500, {0x80a6ac, 0xc2adc0}, {0x123ea1c1, {0x1368f30, 0x27}, {{0x12db9e0, 0x8}, {0x0, 0x0}, ...}})
Dec 04 15:16:37 duchamp go-librespot[733]:         /src/cmd/daemon/player.go:155 +0xfec
Dec 04 15:16:37 duchamp go-librespot[733]: main.(*AppPlayer).handleDealerRequest(0x10ac500, {0x80a6ac, 0xc2adc0}, {0x1090bc0, {0x13683c0, 0x24}, {0x123ea1c1, {0x1368f30, 0x27}, {{0x12db9e0, ...}, ...}}})
Dec 04 15:16:37 duchamp go-librespot[733]:         /src/cmd/daemon/player.go:350 +0xf4
Dec 04 15:16:37 duchamp go-librespot[733]: main.(*AppPlayer).Run(0x10ac500, {0x80a6ac, 0xc2adc0}, 0x127d400)
Dec 04 15:16:37 duchamp go-librespot[733]:         /src/cmd/daemon/player.go:576 +0x4bc
Dec 04 15:16:37 duchamp go-librespot[733]: created by main.(*App).withAppPlayer in goroutine 1
Dec 04 15:16:37 duchamp go-librespot[733]:         /src/cmd/daemon/main.go:232 +0x37c

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

Here an example of the raw message received, before the crash:

Dec 04 15:26:01 duchamp go-librespot[900]: message: {"message_ident":"hm://connect-state/v1/player/command","headers":{"Transfer-Encoding":"gzip"},"payload":{"compressed":"H4sIAAAAAAAA/5VQy26EMAz8l5yptBsK7fZnIkMcGm3ioNgUoRX/XrNIba+9WfPwePwwGZlhQhe9+Wgvfd+9t23fGIE6oThIEfjJ0ZJSYxhJ3LA5j19xPE1mxQHm+DIGvNl2sL7vL6/tbYRgh657G+w1tFdrr6YxY8kZSD0Pg+TnEknULxWIA1YVeBBQRKcySyzEh7QiS6noZlgYj0AFlowq+mEKx0OuXAIWd6ey0h9eE8a7kpBW2NjNCTbHJaN8RpqeOoFIjvUV5xZfHBVxJ272xoRa8m9pfUIMUS/+T/lUpknjtEaFfBTb9/0bNbpJkX8BAAA="},"type":"request","key":"fc2020f2-4d87-4058-9443-f1d34000e2fe"}

I would bet on the protobuf format being faulty/outdated.

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

@devgianlu let me know if you need any other info

devgianlu added a commit that referenced this issue Dec 4, 2024
@devgianlu
Copy link
Owner

I am not entirely sure what this should even do, the payload is empty:

{"message_id":306658336,"target_alias_id":null,"sent_by_device_id":"webapi-cfe923b2d660439caf2b557b21f31221","command":{"endpoint":"transfer","data":"","options":{"restore_paused":"resume","restore_position":"last_known","restore_track":"always_play_something","retain_session":"do_not_retain"},"from_device_identifier":"webapi-cfe923b2d660439caf2b557b21f31221","logging_params":{}}}

I am guessing it's just a matter of making the device active for future playback requsts? The official client also seems to not do anything.

Anyways, I have pushed a simple fix to make it not crash.

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

I haven’t checked what the official client does. I will check later, but in all my tests, the official client does transfer playback. So either:

  1. the official client doesn’t get this sort of message
  2. A subsequent message causes the actual playback transfer

Maybe some sort of state (e.g. from the go-librespot token) causes a faulty message?

I will try to erase the go-librespot state too in case that helps. Do you want me to save any state and share it (privately if it involves the authentication token)?

@devgianlu
Copy link
Owner

Maybe so some sort of state (e.g. from the go-librespot token) causes a faulty message?

I doubt that is the issue, the behaviour I see in the official client is the same as go-librespot, perhaps because I don't have any state. Do you get this issue even you are playing on another device?

Do you want me to save any state and share it (privately if it involves the authentication token)?

There's nothing of real interest in there, just authentication stuff.

@2opremio
Copy link
Contributor Author

2opremio commented Dec 4, 2024

You mean that you are intercepting the messages to the official client while transferring and you also get an empty message?

@devgianlu
Copy link
Owner

You mean that you are intercepting the messages to the official client while transferring and you also get an empty message?

I am not able to check what the official client is receiving because my proxy setup broke for some reason. What I was referring to is that transferring withtout a playback state does nothing on the official client too.

Do you get this issue even when you are playing on another device (e.g. there's a playback valid state)?

@2opremio
Copy link
Contributor Author

When playing in another device it works just fine

@devgianlu
Copy link
Owner

When playing in another device it works just fine

I think this is solved then? The crash should not happen anymore.

@2opremio
Copy link
Contributor Author

Yep, thanks a lot

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants