Becomes unresponsive after first disconnection

[nodgear]

Bot works fine when first joining a voice channel, it connects and plays as usual.
But as soon it disconnects from a voice channel it never comes back, the following error is sent on console every time you join a new voice channel.

Could not find user in VC.

Jul 20 11:29:55.059 ERROR librespot_connect::spirc: AutoplayError: MercuryError    
[...Same error multiple times]

[nodgear]

Quick upddate:

the bot doesn't need to disconnect, you just have to change channels while the bot is running (doesn't even need to be playing) for the bot to go crazy.
restarting the whole server fixes the issue (I'm currently running via docker).
restarting just the container doesn't fix anything

[codetheweb]

Sorry, but I can't reproduce this. Are you running the latest version?

Screen.Recording.2022-07-26.at.5.47.37.PM.mov

[nodgear]

Running latest, directly pulled from docker-hub
Fresh Arch install, only installed requirement and added portainer for convenience.
https://user-images.githubusercontent.com/22383863/181243747-07e44751-b01b-4da0-bad4-ee86fd68b696.mp4

I can confirm librespot works pefectly fine.

[nodgear]

Here's my implementation in NodeJS (Typescript) to confirm the bot has all needed permissions to join voice channels.

firefox_sAvWIteuoJ.mp4

My implementation has problems that i believe to be caused by how event loop works. Like massive delay & sometimes making librespot unable to stop/skip tracks ignoring my spotify commands completely

[codetheweb]

I would double-check the Discord user ID provided to the bot.

Please also try setting the environment variables RUST_BACKTRACE=1 and RUST_LOG=librespot to see if anything useful is logged before it crashes.

[nodgear]

The id is perfectly fine.
Here's the relevant part of the log i got using the requested vars:

aoede-aoede-1  | thread '<unnamed>' panicked at 'Map must not be polled after it returned `Poll::Ready`', /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/futures-util-0.3.19/src/future/future/map.rs:62:17
aoede-aoede-1  | stack backtrace:
aoede-aoede-1  |    0: std::panicking::begin_panic
aoede-aoede-1  |    1: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
aoede-aoede-1  |    2: <futures_util::future::try_future::MapErr<Fut,F> as core::future::future::Future>::poll
aoede-aoede-1  |    3: <librespot_playback::player::PlayerInternal as core::future::future::Future>::poll
aoede-aoede-1  |    4: std::thread::local::LocalKey<T>::with
aoede-aoede-1  |    5: futures_executor::local_pool::block_on
aoede-aoede-1  | note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Here's another log i got by solving the panic above (the panic was in librespot itself).

aoede-aoede-1  | Ready!
aoede-aoede-1  | Invite me with https://discord.com/api/oauth2/authorize?client_id=999240330660556841&permissions=36700160&scope=bot
aoede-aoede-1  | Jul 28 23:04:58.260  INFO librespot_playback::mixer::softmixer: Mixing with softvol and volume control: Linear
aoede-aoede-1  | Jul 28 23:04:58.260 DEBUG librespot_connect::spirc: new Spirc[0]
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot_connect::spirc: canonical_username: 3a3a4glj34s40sw2ppvd1642l
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot::component: new MercuryManager
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot_playback::mixer::mappings: Input volume 32767 mapped to: 50.00%
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot_playback::player: new Player[0]
aoede-aoede-1  | Jul 28 23:04:58.261  INFO librespot_playback::convert: Converting with ditherer: tpdf
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot_playback::player: command=AddEventSender
aoede-aoede-1  | Jul 28 23:04:58.261 DEBUG librespot_playback::player: command=VolumeSet(32767)
aoede-aoede-1  | Jul 28 23:04:58.424 DEBUG librespot_core::mercury: subscribed uri=hm://remote/user/3a3a4glj34s40sw2ppvd1642l/ count=0
aoede-aoede-1  | Jul 28 23:04:58.584 DEBUG librespot_connect::spirc: kMessageTypeNotify "HPC" fad2ba422aba3ccf00724a192939a7755e8e0747 1192122891 1659049498375 kPlayStatusStop
aoede-aoede-1  | Jul 28 23:04:58.584 DEBUG librespot_connect::spirc: kMessageTypeNotify "a9a43064-bdc9-49ff-bf92-b72490598fca" a9a43064-bdc9-49ff-bf92-b72490598fca 1192122891 1659049498375 kPlayStatusStop
aoede-aoede-1  | Jul 28 23:05:08.440 DEBUG librespot_connect::spirc: kMessageTypeLoad "HPC" fad2ba422aba3ccf00724a192939a7755e8e0747 1192132311 1659049498375 kPlayStatusPause
aoede-aoede-1  | Jul 28 23:05:08.440 DEBUG librespot_connect::spirc: State: context_uri: "spotify:playlist:1oii6Nq8VnO2nKznIxqYgi" index: 10 position_ms: 229 status: kPlayStatusPause position_measured_at: 1659049508335 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 10 track {gid: "j\211!c\241.KE\270\316i\031\364\246\364\370"} track {uri: "spotify:local:Akstrv::Missed+Call:153"} track {gid: "\344\276 l?9C2\274%\216:\310v\305k"} track {gid: "\"\245\025\324J\324MD\225,\273\244_\334<\270"} track {gid: "\202\027/\331\254>K\340\256_\251\\\205\306J\362"} track {gid: "\373\2331\237\016\314B5\222\013);\031oF\370"} track {gid: "\207\322\343J|\257O\'\204\035w1?\352\207\021"} track {gid: "i\006HC?\212F\016\263\313\231\301;\305\363q"} track {gid: "7u\247e\270\215B\254\247ue5\004\376\007\227"} track {gid: "OF\362$\316\334C\205\231b\177\213\345\333P\317"} track {gid: "\005C\326&\261n@]\266\312Q*qD\262\211"} track {gid: "I\215\361\034M\310G~\2149_5Z\264\333 "} track {gid: "\n\276\024\305b\302N\330\275x\026\357\274\332TJ"}
aoede-aoede-1  | Jul 28 23:05:08.440 DEBUG librespot_connect::spirc: Frame has 13 tracks
aoede-aoede-1  | Jul 28 23:05:08.440  INFO librespot_connect::spirc: Fetching autoplay context uri
aoede-aoede-1  | Jul 28 23:05:08.441 TRACE librespot_connect::spirc: Sending status to server: [kPlayStatusPause]
aoede-aoede-1  | Jul 28 23:05:08.441 DEBUG librespot_playback::player: command=SetAutoNormaliseAsAlbum(false)
aoede-aoede-1  | Jul 28 23:05:08.441 DEBUG librespot_playback::player: command=Load(SpotifyId { id: 6998367369683902353855350010619933321, audio_type: Track }, false, 229)
aoede-aoede-1  | Jul 28 23:05:08.441 TRACE librespot_connect::spirc: Sending status to server: [kPlayStatusPause]
aoede-aoede-1  | Could not find user in VC.
aoede-aoede-1  | Jul 28 23:05:08.603  INFO librespot_connect::spirc: Autoplay uri resolved to <"spotify:station:playlist:1oii6Nq8VnO2nKznIxqYgi">
aoede-aoede-1  | Jul 28 23:05:08.765 DEBUG librespot_core::mercury: unknown subscription uri=social-connect/v2/session_update
aoede-aoede-1  | Jul 28 23:05:08.924  INFO librespot_playback::player: Loading <Years Ago> with Spotify URI <spotify:track:09VXHPoM8Vm9vDR9YvNT05>
aoede-aoede-1  | Jul 28 23:05:08.924 DEBUG librespot_audio::fetch: File f092c39b4068fce36fe7e3c5204e30ea1e150e19 already in cache
aoede-aoede-1  | Jul 28 23:05:08.924 DEBUG librespot::component: new AudioKeyManager
aoede-aoede-1  | Jul 28 23:05:09.106  INFO librespot_playback::player: <Years Ago> (133402 ms) loaded
aoede-aoede-1  | Jul 28 23:05:09.106 TRACE librespot_connect::spirc: Sending status to server: [kPlayStatusPause]
aoede-aoede-1  | Jul 28 23:05:09.106 TRACE librespot_connect::spirc: ==> kPlayStatusPause
aoede-aoede-1  | Jul 28 23:05:09.533  INFO librespot_connect::spirc: Resolved 50 tracks from <"spotify:playlist:1oii6Nq8VnO2nKznIxqYgi">

The bot just straight up REFUSES to join my voice channel, and my discord ID is correct.

[codetheweb]

I started creating a PR to bump the dependencies, might help with your issue: #17 (still needs some fixes before it'll build).

[oleggtro]

Does this problem still persist?
If yes, maybe have a look at this: https://github.com/jpochyla/psst/blob/master/psst-protocol/src/mercury.rs

[nodgear]

Hello, cloudybyte.
I'm not sure if the problem persists or if it's another problem
but after the first disconnect the audio becomes absolutely trash, because of that i decided to just not try anymore.

[oleggtro]

I've noticed the same issue in the past, but rarely use discord VC these days.

If I'd had to guess I'd say it has something to do with the binary protocol Spotify uses to transmit the audio stream. Something in there probably got changed or mixed up which results in this weird behavior. Can't promise it though.

As I currently don't have time for collab here, @codetheweb doesn't seem interested in looking into this and there are no other contributors this will probably persist for the forseeable future.

However if you're interested in picking this up, I'd be happy to offer a helping hand. @nodgear
(My best guess for fixing is dependency bumping (especially librespot), #17 was originally supposed to fix this though.)

[codetheweb]

As I currently don't have time for collab here, @codetheweb doesn't seem interested in looking into this and there are no other contributors this will probably persist for the forseeable future.

I was waiting for @nodgear to respond. 😅

That being said I do have a lot going on so if you want to take a stab it it @CloudyByte that'd be great.

[myhrmans]

Experiencing the same issue.

[myhrmans]

So I have done some digging around.

The problem seem to be that the player is not really stopped when paused, if you pause the player for a bigger amount of time 10+ while it is in a channel and try to start it, its gonna try to catch up to the new player position. Seems to be something wrong with how the player is paused.

The second issue with Could not find user in VC. comes from here: let guild_id = match guilds.first() {
What if there are two guilds? I had this issue since I had the bot on two guilds. After I removed the bot from all except one I could not reproduce it anymore.

[myhrmans]

Just to clarify:
"guild_id" is then used on multiple places that has to do with what channel the user enters.. and this channel ID might be in another guild_id then the initiated one.