Error handling ("user is already connected") after an exception is thrown

[l3d00m]

Describe the bug
When an exception within librespot-java occurs, I sometimes have to manually restart librespot-java, because any further connection attempts to it are denied with Dropped connection attempt because user is already connected.

To Reproduce
Using ZEROCONF:

1. Somehow manage to throw an unhandled exception (I might open a new issue for that if I manage to reproduce)
2. Librespot-java reacts with something like FATAL Log4JUncaughtExceptionHandler:15 - [player-queue-7462166]
3. In case spotify still shows that you're connected to librespot, just press play or next
4. Or, if it's disconnected, which sometimes is the case just try to reconnect
5. Librespot either throws Dropped connection attempt because user is already connected. or in some cases also an java.lang.IllegalStateException: Buffer is closed!, I don't know whether it's related.

Expected
Either just throw the exception and leave it unhandled, so systemd can detect it and restart my service or allow me to reconnect even tough I'm already connected.

Screenshots/Stracktraces/Logs
I attached an examplary log where that happened

May 06 10:59:24 raspi-server java[12613]: 2020-05-06 10:59:24,811 INFO  DeviceStateHandler:255 - Put state. {ts: 1588755563638, connId: ODk0Mm[truncated], reason: PLAYER_STATE_CHANGED}
May 06 10:59:24 raspi-server java[12613]: 2020-05-06 10:59:24,919 INFO  PlayerQueueEntry:100 - Loaded track. {name: 'ilomilo', artists: 'Billie Eilish', uri: spotify:track:7qEKqBCD2vE5vIBsrUitpD, id: 012b3d9be6dd2f407eb0f3e758b2346b}
May 06 10:59:25 raspi-server java[12613]: 2020-05-06 10:59:24,922 FATAL Log4JUncaughtExceptionHandler:15 - [player-queue-7462166]
May 06 10:59:25 raspi-server java[12613]: java.lang.IllegalArgumentException: TrackId{spotify:track:7qEKqBCD2vE5vIBsrUitpD}
May 06 10:59:25 raspi-server java[12613]:         at xyz.gianlu.librespot.player.StateWrapper.metadataFor(StateWrapper.java:600) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 10:59:25 raspi-server java[12613]:         at xyz.gianlu.librespot.player.Player.metadataFor(Player.java:721) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 10:59:25 raspi-server java[12613]:         at xyz.gianlu.librespot.player.playback.PlayerSession.metadataFor(PlayerSession.java:180) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 10:59:25 raspi-server java[12613]:         at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.load(PlayerQueueEntry.java:104) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 10:59:25 raspi-server java[12613]:         at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.run(PlayerQueueEntry.java:245) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 10:59:25 raspi-server java[12613]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) ~[?:?]
May 06 10:59:25 raspi-server java[12613]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) ~[?:?]
May 06 10:59:25 raspi-server java[12613]:         at java.lang.Thread.run(Thread.java:844) [?:?]
May 06 10:59:25 raspi-server java[12613]: 2020-05-06 10:59:25,103 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|55c462564cca2f379aa5399e96fb8751ea483a8b|spotify:track:7qEKqBCD2vE5vIBsrUitpD|1|2|2, result: 200}
May 06 10:59:59 raspi-server java[12613]: 2020-05-06 10:59:59,852 DEBUG Player:244 - Received command: UpdateContext
May 06 10:59:59 raspi-server java[12613]: 2020-05-06 10:59:59,867 DEBUG DealerClient:108 - Handled request. {key: 6218a36d-dfe7-4b4c-aff0-43636579f9c3, result: SUCCESS}
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,326 DEBUG Player:244 - Received command: Play
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,326 DEBUG Player:297 - Loading context (play), uri: spotify:playlist:37i9dQZF1DXdxcBWuJkbcy
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,339 INFO  StateWrapper:207 - Context has transforming! {url: https://spclient.wg.spotify.com/cuepoints-transitions/v2/decorate, shuffle: true, willRequest: true}
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,720 DEBUG StateWrapper:221 - Updated context with transforming information!
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,728 FATAL Log4JUncaughtExceptionHandler:15 - [player-queue-21358477]
May 06 11:00:00 raspi-server java[12613]: java.lang.IllegalStateException: Buffer is closed!
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.mixing.CircularBuffer.write(CircularBuffer.java:42) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.mixing.MixingLine$SecondOutputStream.write(MixingLine.java:166) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.codecs.VorbisCodec.decodeCurrentPacket(VorbisCodec.java:201) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.codecs.VorbisCodec.readInternal(VorbisCodec.java:153) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.codecs.Codec.writeSomeTo(Codec.java:42) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.run(PlayerQueueEntry.java:295) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:00:00 raspi-server java[12613]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) ~[?:?]
May 06 11:00:00 raspi-server java[12613]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) ~[?:?]
May 06 11:00:00 raspi-server java[12613]:         at java.lang.Thread.run(Thread.java:844) [?:?]
May 06 11:00:00 raspi-server java[12613]: 2020-05-06 11:00:00,762 INFO  DeviceStateHandler:255 - Put state. {ts: 1588755599865, connId: ODk0Mm[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:00:01 raspi-server java[12613]: 2020-05-06 11:00:01,014 DEBUG EventService:48 - Event sent. {body: 12|37|15|8942de66cd50d8975d5d39bb67e4d848c792fb7d|012b3d9be6dd2f407eb0f3e758b2346b|00000000000000000000000000000000|playlist|fwdbtn|playlist|endplay|0|0|382|382|0|0|0|0|0|1|8|0|-1|context|426|0|0|0|0|0|382|382|0|0|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy||f41ffe564e4f426d88740ce70ba661b9||0|1588755563641|0|context|your-library|8.5.56.1186|com.spotify|none|none|422307f82d79a8f76a4f795002fe9c3ac0294a7e|na|none, result: 200}
May 06 11:00:01 raspi-server java[12613]: 2020-05-06 11:00:01,315 DEBUG EventService:48 - Event sent. {body: 10|20|55c462564cca2f379aa5399e96fb8751ea483a8b|012b3d9be6dd2f407eb0f3e758b2346b|0|0|0|0|0|0|0|0|music|-1|-1|-1|-1.000000|-1|-1.000000|-1|-1|-1|-1.000000|-1|-1|-1|-1|-1.000000|-1|0.000000|-1.000000|||unknown|0|0|0|0|0|interactive|0|0|0|0, result: 200}
May 06 11:00:01 raspi-server java[12613]: 2020-05-06 11:00:01,613 DEBUG EventService:48 - Event sent. {body: 372|1|012b3d9be6dd2f407eb0f3e758b2346b|spotify:track:7qEKqBCD2vE5vIBsrUitpD|0|[[8,382]], result: 200}
May 06 11:00:20 raspi-server java[12613]: 2020-05-06 11:00:20,769 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}
May 06 11:00:22 raspi-server java[12613]: 2020-05-06 11:00:22,825 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}
May 06 11:01:50 raspi-server java[12613]: 2020-05-06 11:01:50,783 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}
May 06 11:01:52 raspi-server java[12613]: 2020-05-06 11:01:52,876 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}
May 06 11:02:04 raspi-server java[12613]: 2020-05-06 11:02:04,654 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}
May 06 11:02:06 raspi-server java[12613]: 2020-05-06 11:02:06,735 DEBUG ZeroconfServer:288 - Dropped connection attempt because user is already connected. {username: myusername}

Version/Commit
just compiled 8ba96df

Edit: Know I see that there are some exisiting issues on this, but at least they are all closed so this should be kinda new: #134 (comment) #210

[devgianlu]

The exceptions should disappear. Unluckily you can't just reconnect if an exception is thrown because there is no way to determine whether that was a fatal error.

I may consider removing the "already connected" check that was originally introduced to avoid connection retries even if already connected.

[l3d00m]

Makes kinda sense, removing the check sounds like a good idea though. That way you're no longer locked out.

[Kucheek]

I think the check was introduced while fixing #134 because with my configuration librespot-java always tried to connect twice upon establishing session for the first time.

[devgianlu]

@Kucheek I've removed the check, hopefully your issue doesn't appear again. If it does, I think moving the response sending after the session is ready might fix it. Let me know.

[Kucheek]

@Kucheek I've removed the check, hopefully your issue doesn't appear again. If it does, I think moving the response sending after the session is ready might fix it. Let me know.

Seems OK to me right now. I'd report to you if the issue appears later.

[Kucheek]

This is probably not related to the removed check of connection attempt but I might have run into similar issue as @l3d00m did. In my case librespot-java played happily for some time (1 hour) without any interference from me and when I wanted to stop playback, it ceased to react on any command. App indicated the whole time that I am connected and the playback kept running.

commit 68cd2ab

I had log level set to WARN only, so it might not be of much use, but still better than nothing.:

2020-05-07 14:18:54,705 FATAL Session:1103 - Failed reading packet!
java.io.EOFException: null
        at java.io.DataInputStream.readFully(DataInputStream.java:197) ~[?:1.8.0_222]
        at java.io.DataInputStream.readFully(DataInputStream.java:169) ~[?:1.8.0_222]
        at xyz.gianlu.librespot.crypto.CipherPair.receiveEncoded(CipherPair.java:60) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.core.Session$Receiver.run(Session.java:1095) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 14:47:38,694 FATAL Log4JUncaughtExceptionHandler:15 - [player-queue-28394281]
java.lang.IllegalArgumentException: Unknown uri:
        at xyz.gianlu.librespot.mercury.model.PlayableId.fromUri(PlayableId.java:27) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.mercury.model.PlayableId.from(PlayableId.java:54) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.StateWrapper.getCurrentPlayable(StateWrapper.java:538) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.StateWrapper.metadataFor(StateWrapper.java:598) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.Player.metadataFor(Player.java:721) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.playback.PlayerSession.metadataFor(PlayerSession.java:180) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.load(PlayerQueueEntry.java:104) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.run(PlayerQueueEntry.java:245) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 15:55:17,526 FATAL CdnManager:302 - Failed requesting chunk from network, index: 51
java.net.SocketTimeoutException: timeout
        at okio.SocketAsyncTimeout.newTimeoutException(JvmOkio.kt:143) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okio.AsyncTimeout.access$newTimeoutException(AsyncTimeout.kt:162) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:340) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:449) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:333) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:82) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.core.Session.lambda$createClient$2(Session.java:154) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:197) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okhttp3.internal.connection.RealCall.execute(RealCall.kt:148) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.feeders.cdn.CdnManager$Streamer.request(CdnManager.java:316) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.feeders.cdn.CdnManager$Streamer.request(CdnManager.java:309) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.feeders.cdn.CdnManager$Streamer.requestChunk(CdnManager.java:299) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.feeders.cdn.CdnManager$Streamer.access$1400(CdnManager.java:183) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.feeders.cdn.CdnManager$Streamer$InternalStream.lambda$requestChunkFromStream$0(CdnManager.java:372) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: java.net.SocketException: Socket closed
        at java.net.SocketInputStream.read(SocketInputStream.java:204) ~[?:1.8.0_222]
        at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_222]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) ~[?:1.8.0_222]
        at sun.security.ssl.InputRecord.read(InputRecord.java:503) ~[?:1.8.0_222]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975) ~[?:1.8.0_222]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933) ~[?:1.8.0_222]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) ~[?:1.8.0_222]
        at okio.InputStreamSource.read(JvmOkio.kt:90) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:129) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        ... 27 more
2020-05-07 16:08:50,322 FATAL Session:1103 - Failed reading packet!
java.io.EOFException: null
        at java.io.DataInputStream.readFully(DataInputStream.java:197) ~[?:1.8.0_222]
        at java.io.DataInputStream.readFully(DataInputStream.java:169) ~[?:1.8.0_222]
        at xyz.gianlu.librespot.crypto.CipherPair.receiveEncoded(CipherPair.java:60) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.core.Session$Receiver.run(Session.java:1095) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 16:23:01,198 FATAL Player:542 - An error with the mixer occurred. This is likely a configuration issue, please consult the project repository.
xyz.gianlu.librespot.player.mixing.LineHelper$MixerException: No mixers available for the specified search keywords: [sndrpihifiberry [default]]
        at xyz.gianlu.librespot.player.mixing.LineHelper.findMixer(LineHelper.java:49) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.LineHelper.getLineFor(LineHelper.java:63) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.acquireLine(AudioSink.java:203) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.write(AudioSink.java:228) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink.run(AudioSink.java:152) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 16:23:49,846 WARN  EventService:106 - Did not send event because of missing metrics: 01e91818d8424702607604ad26ceb82b
2020-05-07 16:23:50,346 FATAL Player:542 - An error with the mixer occurred. This is likely a configuration issue, please consult the project repository.
xyz.gianlu.librespot.player.mixing.LineHelper$MixerException: No mixers available for the specified search keywords: [sndrpihifiberry [default]]
        at xyz.gianlu.librespot.player.mixing.LineHelper.findMixer(LineHelper.java:49) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.LineHelper.getLineFor(LineHelper.java:63) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.acquireLine(AudioSink.java:203) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.write(AudioSink.java:228) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink.run(AudioSink.java:152) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 16:23:50,495 WARN  EventService:106 - Did not send event because of missing metrics: 017b4b2eaf0de0d9f698c7f26926ebfc
2020-05-07 16:24:16,522 FATAL Player:542 - An error with the mixer occurred. This is likely a configuration issue, please consult the project repository.
xyz.gianlu.librespot.player.mixing.LineHelper$MixerException: No mixers available for the specified search keywords: [sndrpihifiberry [default]]
        at xyz.gianlu.librespot.player.mixing.LineHelper.findMixer(LineHelper.java:49) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.LineHelper.getLineFor(LineHelper.java:63) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.acquireLine(AudioSink.java:203) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.write(AudioSink.java:228) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink.run(AudioSink.java:152) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-05-07 16:25:35,901 FATAL Player:542 - An error with the mixer occurred. This is likely a configuration issue, please consult the project repository.
xyz.gianlu.librespot.player.mixing.LineHelper$MixerException: No mixers available for the specified search keywords: [sndrpihifiberry [default]]
        at xyz.gianlu.librespot.player.mixing.LineHelper.findMixer(LineHelper.java:49) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.LineHelper.getLineFor(LineHelper.java:63) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.acquireLine(AudioSink.java:203) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink$Output.write(AudioSink.java:228) ~[librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at xyz.gianlu.librespot.player.mixing.AudioSink.run(AudioSink.java:152) [librespot-core-jar-with-dependencies.jar:1.4.0-SNAPSHOT]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

[devgianlu]

Looks like the client had an entry without URI. @Kucheek Did you use the queue?

I've made some changes with 6cbca7a, the exception that caused all the mess has been removed. I think there's still an issue with the reconnection.

[Kucheek]

No, queue was not used at all in that particular session. Standard playlist (not a Daily mix) was played back.

I start to think that the root cause might be in the low-spec RPi 1B I use. Some of the actions that happen almost instantly on more powerful platforms can take few seconds in my case, e.g. when I wake the device from sleep, unlock the screen and open Spotify client, it takes like 2-3 seconds for client to recognize that librespot-java is active and playing. When commands are performed in such moment, it might probably hit librespot-java unprepared when there is no exception catch.

I am aware of that and usually wait few moments before taking any action, but when my wife is using Spotify, she has a bad luck of triggering these exceptions.

I will deploy new build with the above commit and see if I can spot difference. Thank you!

[devgianlu]

I will deploy new build with the above commit and see if I can spot difference.

If you encounter some other problem, please open another issue. This can be closed.

[devgianlu]

I think moving the response sending after the session is ready might fix it.

In the end, I had to move it: #220 (comment), hopefully it is enough.