search

librespot-org / librespot-java

The most up-to-date open source Spotify client
Apache License 2.0
384 stars 94 forks source link

Service silently vanishes and hangs, sigterm times out #398

Open paulbastian opened 3 years ago

paulbastian commented 3 years ago

Describe the bug Hello, the librespot service silently vanishes after some days from the spotify connect list, a restart is needed. Restart shows the app hanging, sig-term times out and needs to be killed, therefore restarting takes quite a lot of time.

To Reproduce unclear

Expected behavior clear ;)

Screenshots/Stracktraces/Logs

-- Journal begins at Sat 2021-06-26 07:13:40 CEST, ends at Mon 2021-09-06 20:35:52 CEST. --
Sep 06 20:35:52 soundpi2 java[21991]: 2021-09-06 20:35:52,535 INFO  Zeroconf:500 - Announced Service{alias='Magnat_Boxen_Kueche', service='spotify-connect', port=6473, text={VERSION=1.0, CPath=/, Stack=SP}, add>
Sep 06 20:35:51 soundpi2 java[21991]: 2021-09-06 20:35:51,059 INFO  ZeroconfServer:472 - Zeroconf HTTP server started successfully on port 6473!
Sep 06 20:35:50 soundpi2 java[21991]: 2021-09-06 20:35:50,895 INFO  Utils:104 - Cryptography restrictions removal not needed.
Sep 06 20:35:48 soundpi2 systemd[1]: Started A spotify playing daemon.
Sep 06 20:35:48 soundpi2 systemd[1]: Stopped A spotify playing daemon.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Failed with result 'timeout'.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Main process exited, code=killed, status=9/KILL
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21986 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21984 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21983 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21960 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21959 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21957 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21956 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21955 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21954 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21953 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21952 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21950 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21949 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21947 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21946 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21944 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21943 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21940 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21939 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21928 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21925 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21922 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21919 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21917 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21916 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21915 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21914 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21910 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21909 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21908 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21905 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21904 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21903 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21902 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21901 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21270 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21268 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21220 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21218 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21211 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21203 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21202 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21197 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21191 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21147 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21137 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21131 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21129 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21128 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21117 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21116 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21115 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21114 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21113 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21112 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21110 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21109 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21106 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21105 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21103 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21102 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 21099 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20920 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20468 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20393 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20313 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20292 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20247 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20237 (zeroconf-client) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20174 (player-queue-13) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20146 (player-queue-23) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 20130 (OkHttp TaskRunn) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 15942 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14118 (pool-6-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14093 (event-service-s) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14091 (put-state-worke) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14090 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14118 (pool-6-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14093 (event-service-s) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14091 (put-state-worke) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14090 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14089 (dealer-schedule) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14088 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14087 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 14086 (session-schedul) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 12195 (pool-5-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 3023 (Okio Watchdog) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 11534 (pool-4-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 9917 (pool-3-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 5004 (pool-2-thread-1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4999 (Java Sound Even) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4971 (zeroconf-io-thr) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4964 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4963 (GC Thread#1) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4960 (Common-Cleaner) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4959 (VM Periodic Tas) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4958 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4957 (Sweeper thread) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4956 (C2 CompilerThre) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4955 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4954 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4953 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4952 (Finalizer) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4951 (Reference Handl) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4950 (n/a) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4949 (G1 Service) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4946 (G1 Main Marker) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4944 (java) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: Killing process 4943 (java) with signal SIGKILL.
Sep 06 20:35:48 soundpi2 systemd[1]: librespot-java.service: State 'stop-sigterm' timed out. Killing.
Sep 06 20:34:18 soundpi2 java[4943]: 2021-09-06 20:34:18,087 TRACE PlayerQueue:157 - Queue has been cleared.
Sep 06 20:34:18 soundpi2 java[4943]: 2021-09-06 20:34:18,086 TRACE PlayerQueue:157 - Queue has been cleared.
Sep 06 20:34:18 soundpi2 systemd[1]: Stopping A spotify playing daemon...
Sep 05 21:16:56 soundpi2 java[4943]: 2021-09-05 21:16:56,306 TRACE DealerClient:114 - Received request. {mid: hm://connect-state/v1/player/command, key: 3d8d7e60-206d-468e-9824-c1c7c3dcd485, pid: 929328141, sen>

Version/Commit Release 1.6.1

Thanks for looking into this! Best regards, Paul

paulbastian commented 3 years ago

Often this behaviour is followed by this error:

Sep 10 13:07:30 soundpi1 java[15479]: 2021-09-10 13:07:30,295 TRACE DealerClient:271 - Scheduled reconnection attempt in 10 seconds...
Sep 10 13:07:30 soundpi1 java[15479]:         at java.lang.Thread.run(Thread.java:831) [?:?]
Sep 10 13:07:30 soundpi1 java[15479]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
Sep 10 13:07:30 soundpi1 java[15479]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
Sep 10 13:07:30 soundpi1 java[15479]:         at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:519) [librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okhttp3.internal.ws.RealWebSocket$connect$1.onResponse(RealWebSocket.kt:195) [librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.kt:293) [librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.kt:102) ~[librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.kt:119) ~[librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okio.RealBufferedSource.readByte(RealBufferedSource.kt:209) ~[librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]:         at okio.RealBufferedSource.require(RealBufferedSource.kt:199) ~[librespot-player.jar:1.6.1]
Sep 10 13:07:30 soundpi1 java[15479]: java.io.EOFException: null
Sep 10 13:07:30 soundpi1 java[15479]: 2021-09-10 13:07:30,293 WARN  DealerClient:403 - An exception occurred. Reconnecting...