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.

Sign up for GitHub

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

Jump to bottom

Deadlock after pause followed by seek #175

Closed
funtax opened this issue Mar 2, 2020 · 4 comments
Closed

Deadlock after pause followed by seek #175

funtax opened this issue Mar 2, 2020 · 4 comments
Labels
bug Something isn't working

Comments

@funtax
Copy link
Contributor

funtax commented Mar 2, 2020 •
edited
Loading

Describe the bug
It seems like there's a deadlock when you play a track, then pause playback, seek and continue.
The issue happened in a custom modification of librespot-java, so I tried again with the official dev-branch today (running mvn + java -jar..).

I ran VisualVM after the issue occured and took a thread-dump, seems like it hangs at "readInternal" in the VorbisCodec.

To Reproduce
Select the device inside Spotify, start a track, then pause playback, seek + press play again

Expected behavior
The playback continues.

Screenshots/Stracktraces/Logs

2020-03-02 16:36:02
Full thread dump OpenJDK 64-Bit Server VM (25.181-b13 mixed mode):

"handle-packet-498746939" #55 prio=5 os_prio=0 tid=0x0000000021c62800 nid=0xd1c waiting on condition [0x00000000254de000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d1ff71a0> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"handle-packet-2116037501" #54 prio=5 os_prio=0 tid=0x0000000021c66000 nid=0x1624 waiting on condition [0x000000002360e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d1ff71a0> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"RMI TCP Connection(2)-10.0.75.1" #53 daemon prio=5 os_prio=0 tid=0x0000000021c5e800 nid=0x4c9c runnable [0x00000000252dd000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <0x00000007746a2068> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(FilterInputStream.java:83)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:555)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$65/572197727.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- <0x00000007746544e0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"JMX server connection timeout 52" #52 daemon prio=5 os_prio=0 tid=0x0000000021c65800 nid=0x4d7c in Object.wait() [0x000000002320f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
- locked <0x0000000774654008> (a [I)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"RMI Scheduler(0)" #51 daemon prio=5 os_prio=0 tid=0x0000000021c5d800 nid=0x2758 waiting on condition [0x000000002047e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000077466af60> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"RMI TCP Connection(idle)" #50 daemon prio=5 os_prio=0 tid=0x0000000021c64800 nid=0x20c8 waiting on condition [0x000000002017e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007746543d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"RMI TCP Accept-0" #49 daemon prio=5 os_prio=0 tid=0x0000000021c5f000 nid=0x439c runnable [0x00000000010be000]
java.lang.Thread.State: RUNNABLE
at java.net.DualStackPlainSocketImpl.accept0(Native Method)
at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
- locked <0x0000000774654c88> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"release-line-scheduler-390944930" #48 prio=5 os_prio=0 tid=0x0000000021c61800 nid=0x3634 waiting on condition [0x00000000011bf000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d2000e68> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"player-runner-writer-862242375" #41 prio=5 os_prio=0 tid=0x0000000021c63000 nid=0x1e40 waiting on condition [0x00000000255de000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007746a4cf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2163)
at xyz.gianlu.librespot.player.mixing.CircularBuffer.awaitSpace(CircularBuffer.java:34)
at xyz.gianlu.librespot.player.mixing.CircularBuffer.write(CircularBuffer.java:48)
at xyz.gianlu.librespot.player.mixing.MixingLine$LowLevelStream.write(MixingLine.java:139)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.decodeCurrentPacket(VorbisCodec.java:218)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.readInternal(VorbisCodec.java:170)
- locked <0x00000007746a5dc8> (a java.lang.Object)
- locked <0x00000007746a5d58> (a xyz.gianlu.librespot.player.codecs.VorbisCodec)
at xyz.gianlu.librespot.player.codecs.Codec.readSome(Codec.java:42)
at xyz.gianlu.librespot.player.PlayerRunner$TrackHandler.run(PlayerRunner.java:770)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- <0x00000007746a5e20> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"OkHttp TaskRunner" #36 daemon prio=5 os_prio=0 tid=0x000000001f7f6800 nid=0x3538 waiting on condition [0x0000000023c0e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d1fe7fd0> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"dealer-scheduler-1832467517" #35 prio=5 os_prio=0 tid=0x000000001f7f9800 nid=0x1b70 waiting on condition [0x0000000023b0f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d2302078> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"Okio Watchdog" #34 daemon prio=5 os_prio=0 tid=0x000000001f7f8000 nid=0x4cfc in Object.wait() [0x0000000023a0e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at okio.AsyncTimeout$Companion.awaitTimeout$okio(AsyncTimeout.kt:314)
at okio.AsyncTimeout$Watchdog.run(AsyncTimeout.kt:201)
- locked <0x00000006d206fe70> (a java.lang.Class for okio.AsyncTimeout)

Locked ownable synchronizers:
- None

"OkHttp TaskRunner" #33 daemon prio=5 os_prio=0 tid=0x000000001f7fd800 nid=0x4f68 in Object.wait() [0x000000002390e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:460)
at okhttp3.internal.concurrent.TaskRunner$RealBackend.coordinatorWait(TaskRunner.kt:293)
at okhttp3.internal.concurrent.TaskRunner.awaitTaskToRun(TaskRunner.kt:217)
at okhttp3.internal.concurrent.TaskRunner$runnable$1.run(TaskRunner.kt:58)
- locked <0x00000006d1fe7ed0> (a okhttp3.internal.concurrent.TaskRunner)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- <0x0000000774655588> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"OkHttp https://gae-dealer.spotify.com/..." #32 prio=5 os_prio=0 tid=0x000000001f7fc000 nid=0x4154 runnable [0x000000002117e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
- locked <0x0000000774655750> (a java.lang.Object)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
- locked <0x0000000774657830> (a sun.security.ssl.AppInputStream)
at okio.InputStreamSource.read(Okio.kt:93)
at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:129)
at okio.RealBufferedSource.request(RealBufferedSource.kt:207)
at okio.RealBufferedSource.require(RealBufferedSource.kt:201)
at okio.RealBufferedSource.readByte(RealBufferedSource.kt:210)
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.kt:113)
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.kt:96)
at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.kt:240)
at okhttp3.internal.ws.RealWebSocket$connect$1.onResponse(RealWebSocket.kt:170)
at okhttp3.RealCall$AsyncCall.run(RealCall.kt:140)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- <0x00000006d1fe7b80> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"MVStore background writer nio:C:/Users/.../Downloads/cache/table.mv.db" #30 daemon prio=5 os_prio=0 tid=0x000000001f7fd000 nid=0x1418 in Object.wait() [0x000000002330f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:3283)
- locked <0x00000006d1fef728> (a java.lang.Object)

Locked ownable synchronizers:
- None

"player-runner-1109571973" #28 prio=5 os_prio=0 tid=0x000000001f7fa800 nid=0x3938 in Object.wait() [0x000000002310f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at xyz.gianlu.librespot.player.PlayerRunner.run(PlayerRunner.java:158)
- locked <0x00000006d1fff108> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"player-runner-looper-430085426" #27 prio=5 os_prio=0 tid=0x000000001f7f7800 nid=0x2824 waiting for monitor entry [0x000000002300f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.readInternal(VorbisCodec.java:149)
- waiting to lock <0x00000007746a5d58> (a xyz.gianlu.librespot.player.codecs.VorbisCodec)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.seek(VorbisCodec.java:74)
at xyz.gianlu.librespot.player.PlayerRunner$Looper.run(PlayerRunner.java:469)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"Java Sound Event Dispatcher" #26 daemon prio=5 os_prio=0 tid=0x000000001f7f9000 nid=0x3f88 in Object.wait() [0x000000002290e000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at com.sun.media.sound.EventDispatcher.dispatchEvents(EventDispatcher.java:182)
- locked <0x00000006d20070f0> (a com.sun.media.sound.EventDispatcher)
at com.sun.media.sound.EventDispatcher.run(EventDispatcher.java:222)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"dealer-looper" #25 prio=5 os_prio=0 tid=0x000000001f496000 nid=0x1e6c waiting on condition [0x000000002127f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d200f0d0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at xyz.gianlu.librespot.dealer.DealerClient$Looper.run(DealerClient.java:234)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"packets-manager-869476785" #23 prio=5 os_prio=0 tid=0x000000001f0e7000 nid=0x1bcc waiting on condition [0x0000000020e7f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d20170a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at xyz.gianlu.librespot.core.PacketsManager$Looper.run(PacketsManager.java:55)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"packets-manager-1204076983" #22 prio=5 os_prio=0 tid=0x000000001f0e6800 nid=0x2408 waiting on condition [0x0000000020c7f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d201f080> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at xyz.gianlu.librespot.core.PacketsManager$Looper.run(PacketsManager.java:55)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"packets-manager-346285552" #21 prio=5 os_prio=0 tid=0x000000001f4cb000 nid=0x1490 waiting on condition [0x0000000020b7f000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d2007288> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at xyz.gianlu.librespot.core.PacketsManager$Looper.run(PacketsManager.java:55)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"session-scheduler-1892226365" #20 prio=5 os_prio=0 tid=0x000000001f60b000 nid=0xeec waiting on condition [0x0000000020a7e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006d200f2e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"session-packet-receiver" #19 prio=5 os_prio=0 tid=0x000000001f08d000 nid=0x410 runnable [0x000000002097e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.DataInputStream.readFully(DataInputStream.java:195)
at java.io.DataInputStream.readFully(DataInputStream.java:169)
at xyz.gianlu.librespot.crypto.CipherPair.receiveEncoded(CipherPair.java:60)
- locked <0x00000006d20003e8> (a xyz.gianlu.librespot.crypto.Shannon)
at xyz.gianlu.librespot.core.Session$Receiver.run(Session.java:933)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"DestroyJavaVM" #17 prio=5 os_prio=0 tid=0x0000000002e38000 nid=0xc04 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"zeroconf-io-thread" #14 prio=5 os_prio=0 tid=0x000000001f2aa000 nid=0x614 runnable [0x000000002007f000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278)
at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000006d201a3b8> (a sun.nio.ch.Util$3)
- locked <0x00000006d201a3c8> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000006d201a338> (a sun.nio.ch.WindowsSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
at xyz.gianlu.zeroconf.Zeroconf$ListenerThread.run(Zeroconf.java:629)

Locked ownable synchronizers:
- None

"zeroconf-http-server" #12 prio=5 os_prio=0 tid=0x000000001f2a7000 nid=0x37fc runnable [0x000000001fd7e000]
java.lang.Thread.State: RUNNABLE
at java.net.DualStackPlainSocketImpl.accept0(Native Method)
at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
- locked <0x00000006d2007838> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at xyz.gianlu.librespot.core.ZeroconfServer$HttpRunner.run(ZeroconfServer.java:379)
at java.lang.Thread.run(Thread.java:748)

Locked ownable synchronizers:
- None

"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x000000001d4b4000 nid=0x4cd0 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C1 CompilerThread3" #9 daemon prio=9 os_prio=2 tid=0x000000001d425000 nid=0x3bc0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C2 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x000000001d420000 nid=0x1c20 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x000000001d3ce000 nid=0x28e0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x000000001d3cc000 nid=0x4794 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000001d41a800 nid=0x4af8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x000000001d419800 nid=0x325c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001c07a000 nid=0x2f20 in Object.wait() [0x000000001e60f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
- locked <0x00000006d1ff7e38> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

Locked ownable synchronizers:
- None

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x000000001c072000 nid=0x1f24 in Object.wait() [0x000000001e50f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000006d1fefad0> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

Locked ownable synchronizers:
- None

"VM Thread" os_prio=2 tid=0x000000001c06e800 nid=0x24a0 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002e86000 nid=0x393c runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002e87800 nid=0x2094 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000002e89000 nid=0x274c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000002e8b000 nid=0x4338 runnable

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x0000000002e8d800 nid=0x4ef4 runnable

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000002e8f000 nid=0x1374 runnable

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x0000000002e92000 nid=0x4dc4 runnable

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x0000000002e94000 nid=0x455c runnable

"VM Periodic Task Thread" os_prio=2 tid=0x000000001d459000 nid=0x4f9c waiting on condition

JNI global references: 382

Version/Commit
Latest jar-with-dependencies and also in the current dev-branch from today
@funtax funtax added the bug Something isn't working label Mar 2, 2020
@funtax
Copy link
Contributor Author

funtax commented Mar 2, 2020

Now I ran librespot-java within IntelliJ in debug-mode and took a thread-dump there.

Maybe this helps:

"player-runner-looper-424190767@2856" prio=5 tid=0x1f nid=NA waiting for monitor entry
java.lang.Thread.State: BLOCKED
waiting for player-runner-writer-1112013456@4487 to release lock on <0x11cf> (a xyz.gianlu.librespot.player.codecs.VorbisCodec)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.readInternal(VorbisCodec.java:149)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.seek(VorbisCodec.java:74)
at xyz.gianlu.librespot.player.PlayerRunner$Looper.run(PlayerRunner.java:474)
at java.lang.Thread.run(Thread.java:834)

==> player-runner-writer-1112013456@4487

"player-runner-writer-1112013456@4487" prio=5 tid=0x2f nid=NA waiting
java.lang.Thread.State: WAITING
blocks player-runner-looper-424190767@2856
at jdk.internal.misc.Unsafe.park(Unsafe.java:-1)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2211)
at xyz.gianlu.librespot.player.mixing.CircularBuffer.awaitSpace(CircularBuffer.java:34)
at xyz.gianlu.librespot.player.mixing.CircularBuffer.write(CircularBuffer.java:48)
at xyz.gianlu.librespot.player.mixing.MixingLine$LowLevelStream.write(MixingLine.java:112)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.decodeCurrentPacket(VorbisCodec.java:218)
at xyz.gianlu.librespot.player.codecs.VorbisCodec.readInternal(VorbisCodec.java:170)
- locked <0x11cf> (a xyz.gianlu.librespot.player.codecs.VorbisCodec)
- locked <0x11d4> (a java.lang.Object)
at xyz.gianlu.librespot.player.codecs.Codec.readSome(Codec.java:42)
at xyz.gianlu.librespot.player.PlayerRunner$TrackHandler.run(PlayerRunner.java:775)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.lang.Thread.run(Thread.java:834)

@devgianlu
Copy link
Member

I know what's happening: seek wants to read and scrap some bytes in order to find the next packet and update the player position, but readInternal is waiting for some space on the buffer, which will never be available due to the paused state, and therefore cannot be accessed.

@devgianlu
Copy link
Member

I've fixed this by removing some unnecessary code that updated the seek position immediately, which is redundant in the terms of precision we need.

@funtax
Copy link
Contributor Author

funtax commented Mar 3, 2020

Great solution, works well :)

@funtax funtax mentioned this issue Apr 20, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@funtax @devgianlu