Stuck on Connecting... then player vanishes #231

Willyarma · 2020-05-14T14:57:39Z

When connecting (using Spotify connect) for the first time after a long while or reboot or app restart, I sometimes get into a situation where the Spotify app sticks on connecting... and then if I try again the librespot player has gone from the list.
This has happened many times, I can get it to fail by restarting my tablet (or just the app) and restarting librespot.

I have tried setting log level to trace but theres no significant info output.

2020-05-14 15:50:31,324 [zeroconf-client-13565548] TRACE ZeroconfServer:447 - Handling request: GET /?action=getInfo&version=2.7.1 HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.57 Android/27 (Alba7Nou), Host=192.168.5.138, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-05-14 15:50:31,355 [zeroconf-client-30172593] DEBUG TimeProvider:73 - Loaded time offset from NTP: 156ms
2020-05-14 15:50:31,814 [zeroconf-client-30172593] INFO  Session:122 - Created new session! {deviceId: af5d50657444cc33ea25a9c4da7492bcbfa11c32, ap: guc3-accesspoint-b-g06f.ap.spotify.com:80, proxy: false}
2020-05-14 15:50:31,814 [zeroconf-client-30172593] INFO  ZeroconfServer:343 - Accepted new user from Alba7Nou. {deviceId: af5d50657444cc33ea25a9c4da7492bcbfa11c32}

Then there is no furthur output.

I have tested it on an iPad, Android tablet and an Android phone.

The text was updated successfully, but these errors were encountered:

Willyarma · 2020-05-14T15:00:20Z

If I restart librespot when its stuck, it then works normally.
Also I've had it where when switching back to play on the device it wont play and I can't seek, going to the next track fixes it.

Willyarma · 2020-05-14T15:10:46Z

I've tested using version 122 and 131 and snapshot. I've just noticed the app was updated for android today and ipad 3 days ago, do you think something could have been broken?

devgianlu · 2020-05-15T13:50:31Z

I suppose you are running the latest commit. Is that correct?

Willyarma · 2020-05-15T13:56:37Z

Yes, I built it from source this morning.

devgianlu · 2020-05-15T14:09:59Z

Should be fixed now.

Willyarma · 2020-05-15T14:30:49Z

Thanks, but It's still happening.
I'm running 2 instances of librespot and if the first one connects ok, on switching to the second one it sticks on Connecting... and then it disappears as before. It keeps happening even if I restart librespot until I skip track, its a bit random and dosent always follow what I just said.

devgianlu · 2020-05-15T16:31:40Z

I've made some other changes to that part of the code, not sure if anything should change. Could you post a new log with the Spotify apps versions?

Willyarma · 2020-05-15T16:58:35Z

I've just built it again from the latest source.

It took me a few goes this time to replicate.

The log dosent say much (in TRACE mode), on selecting I only get this:

2020-05-15 17:50:20,571 INFO  Session:125 - Created new session! {deviceId: c8aebde20a55e5b5617af4d78f896bad52aa6ea2, ap: guc3-accesspoint-b-5pkh.ap.spotify.com:80, proxy: false}
2020-05-15 17:50:20,571 INFO  ZeroconfServer:345 - Accepted new user from Alba7Nou. {deviceId: c8aebde20a55e5b5617af4d78f896bad52aa6ea2}

If I try again the app comes up with a popup and asks if I want to continue listening on this player or listen on this tablet, its as if its only partly switched over.
Then the player disappears from the app.

This was on my android tablet running the Spotify app version 8.5.57.1164
My phone is the same version and iPad is 8.5.57 although I havent tried these today.

devgianlu · 2020-05-16T07:22:54Z

I really can't tell what's happening there. It seems to stop before sending the response or during the connection process. Are you able to create a dump (with VisualVM for example) after you have selected to connect with librespot and it's stuck?

Willyarma · 2020-05-16T09:42:58Z

2020-05-16 10:42:01
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.0.1+7 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x0000020c9d631a10, length=34, elements={
0x0000020c9b36d800, 0x0000020c9bbf2000, 0x0000020c9bc0a800, 0x0000020c9bc0e800,
0x0000020c9bc10000, 0x0000020c9bc11000, 0x0000020c9bc23000, 0x0000020c9bc34800,
0x0000020c9bd5c800, 0x0000020c9bd5e000, 0x0000020c9c3d4800, 0x0000020c9c24d800,
0x0000020c9c249800, 0x0000020c9c4e1800, 0x0000020c9c483800, 0x0000020c9c57d800,
0x0000020c9c5ef800, 0x0000020c9c5f4800, 0x0000020c9c5f2000, 0x0000020c9c5f3000,
0x0000020c9c5f3800, 0x0000020c9c5f5000, 0x0000020c9c5f6000, 0x0000020c9c5f0800,
0x0000020c9c5f7000, 0x0000020c9c5f1000, 0x0000020c9c67e000, 0x0000020c9c67d800,
0x0000020c9c67f000, 0x0000020c9c680800, 0x0000020c9c681800, 0x0000020c9c682000,
0x0000020c9c684000, 0x0000020c9c683000
}

"Reference Handler" #2 daemon prio=10 os_prio=2 cpu=15.63ms elapsed=219.52s tid=0x0000020c9b36d800 nid=0xcec waiting on condition  [0x000000d626efe000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
        at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:241)
        at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:213)

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=1 cpu=0.00ms elapsed=219.52s tid=0x0000020c9bbf2000 nid=0xe08 in Object.wait()  [0x000000d626ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait([email protected]/Native Method)
        - waiting on <0x00000007024f9f58> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
        - locked <0x00000007024f9f58> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
        at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:170)

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 cpu=0.00ms elapsed=219.52s tid=0x0000020c9bc0a800 nid=0x2dc runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Attach Listener" #5 daemon prio=5 os_prio=2 cpu=15.63ms elapsed=219.52s tid=0x0000020c9bc0e800 nid=0x2ea8 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Service Thread" #6 daemon prio=9 os_prio=0 cpu=0.00ms elapsed=219.52s tid=0x0000020c9bc10000 nid=0x2ea4 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 cpu=1109.38ms elapsed=219.52s tid=0x0000020c9bc11000 nid=0x2bd8 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
        - None

"C1 CompilerThread0" #10 daemon prio=9 os_prio=2 cpu=671.88ms elapsed=219.52s tid=0x0000020c9bc23000 nid=0x344c waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
        - None

"Sweeper thread" #11 daemon prio=9 os_prio=2 cpu=15.63ms elapsed=219.52s tid=0x0000020c9bc34800 nid=0x2b54 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Notification Thread" #12 daemon prio=9 os_prio=0 cpu=0.00ms elapsed=219.50s tid=0x0000020c9bd5c800 nid=0x3148 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Common-Cleaner" #13 daemon prio=8 os_prio=1 cpu=15.63ms elapsed=219.50s tid=0x0000020c9bd5e000 nid=0x1090 in Object.wait()  [0x000000d6278ff000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait([email protected]/Native Method)
        - waiting on <no object reference available>
        at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
        - locked <0x00000007024f6978> (a java.lang.ref.ReferenceQueue$Lock)
        at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:148)
        at java.lang.Thread.run([email protected]/Thread.java:832)
        at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:134)

   Locked ownable synchronizers:
        - None

"Log4j2-TF-1-AsyncLoggerConfig-1" #16 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=218.73s tid=0x0000020c9c3d4800 nid=0x3ab4 runnable  [0x000000d6279fe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
        - parking to wait for  <0x00000007024fa340> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos([email protected]/AbstractQueuedSynchronizer.java:1661)
        at com.lmax.disruptor.TimeoutBlockingWaitStrategy.waitFor(TimeoutBlockingWaitStrategy.java:38)
        at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
        at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:159)
        at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - None

"zeroconf-http-server" #18 prio=5 os_prio=0 cpu=0.00ms elapsed=218.21s tid=0x0000020c9c24d800 nid=0x19b0 runnable  [0x000000d6280ff000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.accept([email protected]/Native Method)
        at sun.nio.ch.NioSocketImpl.accept([email protected]/NioSocketImpl.java:755)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:684)
        at java.net.ServerSocket.platformImplAccept([email protected]/ServerSocket.java:650)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:626)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:583)
        at java.net.ServerSocket.accept([email protected]/ServerSocket.java:540)
        at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.run(ZeroconfServer.java:420)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - <0x000000071129daf8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"zeroconf-io-thread" #19 prio=5 os_prio=0 cpu=15.63ms elapsed=217.96s tid=0x0000020c9c249800 nid=0x339c runnable  [0x000000d6281ff000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071130d410> (a sun.nio.ch.Util$2)
        - locked <0x000000071130d380> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at xyz.gianlu.zeroconf.Zeroconf$ListenerThread.run(Zeroconf.java:646)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-1" #21 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c4e1800 nid=0x55c runnable  [0x000000d6282fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x00000007113173c0> (a sun.nio.ch.Util$2)
        - locked <0x0000000711317330> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-2" #22 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c483800 nid=0x2a70 runnable  [0x000000d6283fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x00000007113107d0> (a sun.nio.ch.Util$2)
        - locked <0x0000000711310740> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-3" #23 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c57d800 nid=0x2be8 runnable  [0x000000d6284fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x00000007113037b8> (a sun.nio.ch.Util$2)
        - locked <0x0000000711303728> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-4" #24 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5ef800 nid=0x30b0 runnable  [0x000000d6285fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071131a780> (a sun.nio.ch.Util$2)
        - locked <0x000000071131a6f0> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-5" #25 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f4800 nid=0x27bc runnable  [0x000000d6286fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x0000000711313af8> (a sun.nio.ch.Util$2)
        - locked <0x0000000711313a68> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-6" #26 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f2000 nid=0x1fd4 runnable  [0x000000d6287fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x0000000711306ae0> (a sun.nio.ch.Util$2)
        - locked <0x0000000711306a50> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-7" #27 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f3000 nid=0x2d5c runnable  [0x000000d6288fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x0000000711313ea0> (a sun.nio.ch.Util$2)
        - locked <0x0000000711313d48> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-8" #28 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f3800 nid=0x3248 runnable  [0x000000d6289fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071131daa8> (a sun.nio.ch.Util$2)
        - locked <0x000000071131da18> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-9" #29 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f5000 nid=0x23f4 runnable  [0x000000d628afe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x0000000711309ec0> (a sun.nio.ch.Util$2)
        - locked <0x0000000711309d78> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-10" #30 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f6000 nid=0x2b04 runnable  [0x000000d628bff000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x0000000711324470> (a sun.nio.ch.Util$2)
        - locked <0x00000007113243e0> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-11" #31 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f0800 nid=0x41b0 runnable  [0x000000d628cfe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071132e4f8> (a sun.nio.ch.Util$2)
        - locked <0x000000071132e468> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 I/O-12" #32 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f7000 nid=0x42c8 runnable  [0x000000d628dfe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071131de40> (a sun.nio.ch.Util$2)
        - locked <0x000000071131dcf8> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"XNIO-1 Accept" #33 prio=5 os_prio=0 cpu=0.00ms elapsed=216.29s tid=0x0000020c9c5f1000 nid=0x3ac8 runnable  [0x000000d628efe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0([email protected]/Native Method)
        at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll([email protected]/WindowsSelectorImpl.java:357)
        at sun.nio.ch.WindowsSelectorImpl.doSelect([email protected]/WindowsSelectorImpl.java:182)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:129)
        - locked <0x000000071133a5b0> (a sun.nio.ch.Util$2)
        - locked <0x000000071133a520> (a sun.nio.ch.WindowsSelectorImpl)
        at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:146)
        at org.xnio.nio.WorkerThread.run(WorkerThread.java:532)

   Locked ownable synchronizers:
        - None

"DestroyJavaVM" #34 prio=5 os_prio=0 cpu=1078.13ms elapsed=216.26s tid=0x0000020c9c67e000 nid=0x384c waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-0" #35 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=52.20s tid=0x0000020c9c67d800 nid=0x3fa4 runnable  [0x000000d6264fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.accept([email protected]/Native Method)
        at sun.nio.ch.NioSocketImpl.accept([email protected]/NioSocketImpl.java:755)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:684)
        at java.net.ServerSocket.platformImplAccept([email protected]/ServerSocket.java:650)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:626)
        at java.net.ServerSocket.implAccept([email protected]/ServerSocket.java:583)
        at java.net.ServerSocket.accept([email protected]/ServerSocket.java:540)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept([email protected]/LocalRMIServerSocketFactory.java:52)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop([email protected]/TCPTransport.java:413)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run([email protected]/TCPTransport.java:377)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - <0x0000000711288730> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"RMI TCP Connection(idle)" #36 daemon prio=5 os_prio=0 cpu=62.50ms elapsed=52.19s tid=0x0000020c9c67f000 nid=0x464 waiting on condition  [0x000000d6265fe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
        - parking to wait for  <0x0000000711324868> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill([email protected]/SynchronousQueue.java:462)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer([email protected]/SynchronousQueue.java:361)
        at java.util.concurrent.SynchronousQueue.poll([email protected]/SynchronousQueue.java:937)
        at java.util.concurrent.ThreadPoolExecutor.getTask([email protected]/ThreadPoolExecutor.java:1055)
        at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1116)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:630)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - None

"RMI Scheduler(0)" #37 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=52.18s tid=0x0000020c9c680800 nid=0x2e4c waiting on condition  [0x000000d6266ff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
        - parking to wait for  <0x000000071132eaf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos([email protected]/AbstractQueuedSynchronizer.java:1661)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask([email protected]/ThreadPoolExecutor.java:1056)
        at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1116)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:630)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - None

"JMX server connection timeout 38" #38 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=52.18s tid=0x0000020c9c681800 nid=0x3d48 in Object.wait()  [0x000000d6290fe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait([email protected]/Native Method)
        - waiting on <no object reference available>
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run([email protected]/ServerCommunicatorAdmin.java:171)
        - locked <0x000000071136a750> (a [I)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - None

"RMI TCP Connection(2)-192.168.5.138" #39 daemon prio=5 os_prio=0 cpu=125.00ms elapsed=51.14s tid=0x0000020c9c682000 nid=0x2bc4 runnable  [0x000000d6291fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.poll([email protected]/Native Method)
        at sun.nio.ch.NioSocketImpl.park([email protected]/NioSocketImpl.java:181)
        at sun.nio.ch.NioSocketImpl.timedRead([email protected]/NioSocketImpl.java:285)
        at sun.nio.ch.NioSocketImpl.implRead([email protected]/NioSocketImpl.java:309)
        at sun.nio.ch.NioSocketImpl.read([email protected]/NioSocketImpl.java:350)
        at sun.nio.ch.NioSocketImpl$1.read([email protected]/NioSocketImpl.java:803)
        at java.net.Socket$SocketInputStream.read([email protected]/Socket.java:982)
        at java.io.BufferedInputStream.fill([email protected]/BufferedInputStream.java:244)
        at java.io.BufferedInputStream.read([email protected]/BufferedInputStream.java:263)
        - locked <0x0000000711362780> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read([email protected]/FilterInputStream.java:82)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages([email protected]/TCPTransport.java:569)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0([email protected]/TCPTransport.java:828)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0([email protected]/TCPTransport.java:705)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$175/0x0000000800d15040.run([email protected]/Unknown Source)
        at java.security.AccessController.executePrivileged([email protected]/AccessController.java:753)
        at java.security.AccessController.doPrivileged([email protected]/AccessController.java:391)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run([email protected]/TCPTransport.java:704)
        at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1130)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:630)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - <0x00000007112802a8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        - <0x0000000711362b50> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"zeroconf-client-120996864" #40 prio=5 os_prio=0 cpu=203.13ms elapsed=38.11s tid=0x0000020c9c684000 nid=0x3260 runnable  [0x000000d6292fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.SocketDispatcher.read0([email protected]/Native Method)
        at sun.nio.ch.SocketDispatcher.read([email protected]/SocketDispatcher.java:46)
        at sun.nio.ch.NioSocketImpl.tryRead([email protected]/NioSocketImpl.java:261)
        at sun.nio.ch.NioSocketImpl.implRead([email protected]/NioSocketImpl.java:312)
        at sun.nio.ch.NioSocketImpl.read([email protected]/NioSocketImpl.java:350)
        at sun.nio.ch.NioSocketImpl$1.read([email protected]/NioSocketImpl.java:803)
        at java.net.Socket$SocketInputStream.read([email protected]/Socket.java:982)
        at java.net.Socket$SocketInputStream.read([email protected]/Socket.java:977)
        at java.io.DataInputStream.readInt([email protected]/DataInputStream.java:391)
        at xyz.gianlu.librespot.core.Session.connect(Session.java:240)
        at xyz.gianlu.librespot.core.ZeroconfServer.handleAddUser(ZeroconfServer.java:362)
        at xyz.gianlu.librespot.core.ZeroconfServer.access$100(ZeroconfServer.java:39)
        at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.handleRequest(ZeroconfServer.java:440)
        at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:515)
        at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.lambda$run$1(ZeroconfServer.java:423)
        at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner$$Lambda$189/0x0000000800d45440.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1130)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:630)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - <0x0000000711132a30> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        - <0x00000007113ef8c8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"zeroconf-client-50970686" #41 prio=5 os_prio=0 cpu=0.00ms elapsed=14.17s tid=0x0000020c9c683000 nid=0x317c waiting on condition  [0x000000d6298ff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
        - parking to wait for  <0x000000071137e860> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill([email protected]/SynchronousQueue.java:462)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer([email protected]/SynchronousQueue.java:361)
        at java.util.concurrent.SynchronousQueue.poll([email protected]/SynchronousQueue.java:937)
        at java.util.concurrent.ThreadPoolExecutor.getTask([email protected]/ThreadPoolExecutor.java:1055)
        at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1116)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:630)
        at java.lang.Thread.run([email protected]/Thread.java:832)

   Locked ownable synchronizers:
        - None

"VM Thread" os_prio=2 cpu=31.25ms elapsed=219.52s tid=0x0000020c9b365800 nid=0x39d0 runnable  

"GC Thread#0" os_prio=2 cpu=0.00ms elapsed=219.53s tid=0x0000020cf531b800 nid=0x97c runnable  

"GC Thread#1" os_prio=2 cpu=0.00ms elapsed=218.60s tid=0x0000020c9c43e800 nid=0x2d0c runnable  

"GC Thread#2" os_prio=2 cpu=0.00ms elapsed=218.60s tid=0x0000020c9c43f000 nid=0x3150 runnable  

"GC Thread#3" os_prio=2 cpu=0.00ms elapsed=218.60s tid=0x0000020c9c440000 nid=0x4050 runnable  

"GC Thread#4" os_prio=2 cpu=0.00ms elapsed=218.60s tid=0x0000020c9c445000 nid=0xe74 runnable  

"GC Thread#5" os_prio=2 cpu=0.00ms elapsed=218.60s tid=0x0000020c9c445800 nid=0x3d44 runnable  

"GC Thread#6" os_prio=2 cpu=0.00ms elapsed=32.12s tid=0x0000020c9c723800 nid=0x31c0 runnable  

"GC Thread#7" os_prio=2 cpu=0.00ms elapsed=32.12s tid=0x0000020c9c743000 nid=0x1bbc runnable  

"GC Thread#8" os_prio=2 cpu=0.00ms elapsed=32.12s tid=0x0000020c9c743800 nid=0x2ed0 runnable  

"GC Thread#9" os_prio=2 cpu=0.00ms elapsed=32.12s tid=0x0000020c9be21800 nid=0x2cb0 runnable  

"G1 Main Marker" os_prio=2 cpu=0.00ms elapsed=219.53s tid=0x0000020cf533c800 nid=0x3e24 runnable  

"G1 Conc#0" os_prio=2 cpu=15.63ms elapsed=219.53s tid=0x0000020cf533e800 nid=0x3e18 runnable  

"G1 Conc#1" os_prio=2 cpu=15.63ms elapsed=14.03s tid=0x0000020c9d510800 nid=0x39c runnable  

"G1 Conc#2" os_prio=2 cpu=0.00ms elapsed=14.03s tid=0x0000020c9d6a8800 nid=0x3550 runnable  

"G1 Refine#0" os_prio=2 cpu=0.00ms elapsed=219.53s tid=0x0000020c9b253000 nid=0x29ec runnable  

"G1 Young RemSet Sampling" os_prio=2 cpu=0.00ms elapsed=219.53s tid=0x0000020c9b254800 nid=0x413c runnable  
"VM Periodic Task Thread" os_prio=2 cpu=0.00ms elapsed=219.50s tid=0x0000020c9bd5d800 nid=0x18ac waiting on condition  

JNI global refs: 18, weak refs: 0

Willyarma · 2020-05-16T09:45:40Z

I have a heap dump too, but I dont know how to paste that

devgianlu · 2020-05-16T09:51:13Z

As can be seen in the dump, the thread zeroconf-client-120996864 is stuck waiting a response from the Spotify server.

Are you able to start librespot with username and password? Are the two instances running on the same machine?

I have a heap dump too, but I dont know how to paste that

The one you sent is fine.

Willyarma · 2020-05-16T09:56:49Z

Yes the instances are on the same machine, I am spawning them from node.js (child_process) each with their own unique api port. I can test with username and password but I dont want to use it that way in the end as its meant for visitors and friends etc..

Willyarma · 2020-05-16T10:12:32Z

If its waiting from the Spotify server, could it be a wiered internet connection issue? I have multi WAN set up on my router with 4G as my main connection and a slow ADSL connection, I am just trying it with 4G turned off and its not failed yet, I'll keep testing that.

devgianlu · 2020-05-16T10:18:56Z

I've just tried running two instances in two different folders from the command line and it worked fine. Could you try doing it manually?

My steps:

Create folder 1 and 2
Paste JAR in both folders
Edit the configuration file to have different names
Run the JAR executable from two terminals located in the two folders
Switch between the two multiple times

I am thinking that there could be an issue with the IP of two clients being the same to the receiving server. There are multiple APs that the client can connect to, if the two instances happen to connect to the same one, the problem occurs.

A simple test confirmed that it is not the case.

Willyarma · 2020-05-16T10:29:14Z

It's not failed yet since turning off 4G, I'll keep trying.....

Sorry for wasting your time, but it was a big help that you pointed out that it was stuck waiting for the Spotify server, to be honest I can't understand those logs. Thank you very much for your help.

I'll close the issue after I've tested it for a while.

Willyarma · 2020-05-18T12:56:15Z

All seems good now.
Are you able to trap this stuck condition and show something in the log or restart / recover?

devgianlu · 2020-05-18T13:51:02Z

Not really, because it is just a network issue. I could try and set a timeout for the socket, but that would influence other components across the project.

Willyarma added the bug Something isn't working label May 14, 2020

devgianlu added a commit that referenced this issue May 15, 2020

Better version of Zeroconf connection check (#225 , #229, #231)

a03b16c

Willyarma closed this as completed May 18, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stuck on Connecting... then player vanishes #231

Stuck on Connecting... then player vanishes #231

Willyarma commented May 14, 2020 •

edited

Loading

Willyarma commented May 14, 2020 •

edited

Loading

Willyarma commented May 14, 2020 •

edited

Loading

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020 •

edited

Loading

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020 •

edited by devgianlu

Loading

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020 •

edited

Loading

Willyarma commented May 16, 2020

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020

Willyarma commented May 16, 2020

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020 •

edited

Loading

Willyarma commented May 18, 2020

devgianlu commented May 18, 2020

Stuck on Connecting... then player vanishes #231

Stuck on Connecting... then player vanishes #231

Comments

Willyarma commented May 14, 2020 • edited Loading

Willyarma commented May 14, 2020 • edited Loading

Willyarma commented May 14, 2020 • edited Loading

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020 • edited Loading

devgianlu commented May 15, 2020

Willyarma commented May 15, 2020 • edited by devgianlu Loading

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020 • edited Loading

Willyarma commented May 16, 2020

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020

Willyarma commented May 16, 2020

devgianlu commented May 16, 2020

Willyarma commented May 16, 2020 • edited Loading

Willyarma commented May 18, 2020

devgianlu commented May 18, 2020

Willyarma commented May 14, 2020 •

edited

Loading

Willyarma commented May 14, 2020 •

edited

Loading

Willyarma commented May 14, 2020 •

edited

Loading

Willyarma commented May 15, 2020 •

edited

Loading

Willyarma commented May 15, 2020 •

edited by devgianlu

Loading

Willyarma commented May 16, 2020 •

edited

Loading

Willyarma commented May 16, 2020 •

edited

Loading