search

librespot-org / librespot-java

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

Regular Disconnects (sometimes precisely after 30 Minutes?) #328

Open paulbastian opened 3 years ago

paulbastian commented 3 years ago

Describe the bug It seems in the logs that the connection is reset after 30 minutes.

Expected behavior I'm not sure if this is regular behaviour of not, however my music sometimes stops playing which is unfortunate.

Screenshots/Stracktraces/Logs

Mar 13 12:05:08 soundpi1 java[313]: 2021-03-13 12:05:08,781 DEBUG PlayerSession:267 - PlayerQueueEntry{0104f9a4ceb0ee51c89660e35259ce9c} has been added to the output. {sessionId: jdl9/Px4KEJiLhDrGmAPFQ, pos: 1,>
Mar 13 12:05:08 soundpi1 java[313]: 2021-03-13 12:05:08,780 DEBUG CrossfadeController:176 - Changed fade out. {curr: null, custom: false, why: FORWARD_BTN, id: 0119e001ddc4f3513b72050abd179f53}
Mar 13 12:05:08 soundpi1 java[313]: 2021-03-13 12:05:08,779 DEBUG Player:253 - Loading track, id: TrackId{spotify:track:0oUuKR883ZrA6X7snDF5r3}, session: jdl9/Px4KEJiLhDrGmAPFQ, playback: 0119e001ddc4f3513b7205>
Mar 13 12:05:08 soundpi1 java[313]: 2021-03-13 12:05:08,770 DEBUG Player:293 - Received command: SkipNext
Mar 13 12:05:08 soundpi1 java[313]: 2021-03-13 12:05:08,769 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 75c0109b-015f-4e32-83ae-7dfe78ec0b89, pid: 725806198, sende>
Mar 13 12:05:04 soundpi1 java[313]: 2021-03-13 12:05:04,311 DEBUG DealerClient:109 - Handled request. {key: 019ff9b0-1210-4edb-9c4f-700c417e0155, result: SUCCESS}
Mar 13 12:05:04 soundpi1 java[313]: 2021-03-13 12:05:04,310 DEBUG Player:293 - Received command: Pause
Mar 13 12:05:04 soundpi1 java[313]: 2021-03-13 12:05:04,309 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 019ff9b0-1210-4edb-9c4f-700c417e0155, pid: 725801726, sende>
Mar 13 11:57:06 soundpi1 java[313]: 2021-03-13 11:57:06,517 DEBUG DealerClient:109 - Handled request. {key: e068f81a-264d-4a7e-b4bb-81a2a3be352d, result: SUCCESS}
Mar 13 11:57:06 soundpi1 java[313]: 2021-03-13 11:57:06,514 DEBUG Player:293 - Received command: Pause
Mar 13 11:57:06 soundpi1 java[313]: 2021-03-13 11:57:06,513 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: e068f81a-264d-4a7e-b4bb-81a2a3be352d, pid: 725323925, sende>
Mar 13 11:50:27 soundpi1 java[313]: 2021-03-13 11:50:27,403 TRACE DeviceStateHandler:160 - Received cluster update at 1615632627392: cluster { timestamp: 1615632627352 active_device_id: "fad17b9e99e43f657cfd4d3>
Mar 13 11:50:26 soundpi1 java[313]: 2021-03-13 11:50:26,973 TRACE DeviceStateHandler:160 - Received cluster update at 1615632626969: cluster { timestamp: 1615632626915 active_device_id: "fad17b9e99e43f657cfd4d3>
Mar 13 11:40:26 soundpi1 java[313]: 2021-03-13 11:40:26,836 TRACE DeviceStateHandler:160 - Received cluster update at 1615632026831: cluster { timestamp: 1615632026777 active_device_id: "fad17b9e99e43f657cfd4d3>
Mar 13 11:40:26 soundpi1 java[313]: 2021-03-13 11:40:26,364 TRACE DeviceStateHandler:160 - Received cluster update at 1615632026360: cluster { timestamp: 1615632026321 active_device_id: "fad17b9e99e43f657cfd4d3>
Mar 13 11:36:58 soundpi1 java[313]: 2021-03-13 11:36:58,943 DEBUG PlayerQueueEntry:209 - PlayerQueueEntry{0119e001ddc4f3513b72050abd179f53} has been removed from output.
Mar 13 11:36:58 soundpi1 java[313]: 2021-03-13 11:36:58,939 TRACE MixingLine:169 - Toggle first channel: false
Mar 13 11:36:58 soundpi1 java[313]: 2021-03-13 11:36:58,938 DEBUG PlayerQueueEntry:305 - Player time offset is 1150. {id: 0119e001ddc4f3513b72050abd179f53}
Mar 13 11:36:40 soundpi1 java[313]: 2021-03-13 11:36:40,451 INFO  Session:310 - Connected successfully!
Mar 13 11:36:39 soundpi1 java[313]:         at java.lang.Thread.run(Thread.java:832) [?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.common.AsyncProcessor.lambda$submit$1(AsyncProcessor.java:40) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.common.AsyncWorker.lambda$new$0(AsyncWorker.java:20) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.core.EventService.lambda$new$0(EventService.java:28) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.mercury.MercuryClient.sendSync(MercuryClient.java:73) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.mercury.MercuryClient.send(MercuryClient.java:158) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.core.Session.send(Session.java:518) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.core.Session.sendUnchecked(Session.java:479) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at xyz.gianlu.librespot.crypto.CipherPair.sendEncoded(CipherPair.java:48) ~[librespot-player.jar:1.5.4]
Mar 13 11:36:39 soundpi1 java[313]:         at java.io.FilterOutputStream.write(FilterOutputStream.java:108) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at java.io.DataOutputStream.write(DataOutputStream.java:106) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at java.net.Socket$SocketOutputStream.write(Socket.java:1051) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:826) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:440) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:411) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at sun.nio.ch.NioSocketImpl.beginWrite(NioSocketImpl.java:366) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]:         at sun.nio.ch.NioSocketImpl.ensureOpenAndConnected(NioSocketImpl.java:165) ~[?:?]
Mar 13 11:36:39 soundpi1 java[313]: java.net.SocketException: Socket closed
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,818 ERROR EventService:37 - Failed sending event: EventBuilder{274|3|2|2|62659edacd0a09bfe0786320788fcb81d886931a|spotify:track:0oUuKR883ZrA6X7snDF5r3|1|2>
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,816 TRACE MercuryClient:140 - Send Mercury request, seq: 118, uri: hm://event-service/v1/events, method: POST
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,730 TRACE Session:1367 - Session.Receiver stopped
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,729 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,683 DEBUG CrossfadeController:176 - Changed fade out. {curr: null, custom: false, why: TRACK_DONE, id: 0119e001ddc4f3513b72050abd179f53}
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,682 TRACE PlayerSession:146 - PlayerQueueEntry{0104f9a4ceb0ee51c89660e35259ce9c} started loading.
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,682 TRACE PlayerQueue:66 - PlayerQueueEntry{0104f9a4ceb0ee51c89660e35259ce9c} added to queue.
Mar 13 11:36:39 soundpi1 java[313]: 2021-03-13 11:36:39,681 TRACE PlayerQueueEntry:76 - Created new PlayerQueueEntry{0104f9a4ceb0ee51c89660e35259ce9c}.
Mar 13 11:36:22 soundpi1 java[313]: 2021-03-13 11:36:22,640 TRACE CdnManager:261 - Chunk 16/17 completed, cached: false, stream: {fileId: 02B4ABCBCC7667371B14745F5E44B4353C43A4AA}
Mar 13 11:36:12 soundpi1 java[313]: 2021-03-13 11:36:12,295 TRACE CdnManager:261 - Chunk 15/17 completed, cached: false, stream: {fileId: 02B4ABCBCC7667371B14745F5E44B4353C43A4AA}
Mar 13 11:36:01 soundpi1 java[313]: 2021-03-13 11:36:01,517 TRACE CdnManager:261 - Chunk 14/17 completed, cached: false, stream: {fileId: 02B4ABCBCC7667371B14745F5E44B4353C43A4AA}

Also, ad night when not playing music:

Mar 13 02:51:47 soundpi1 java[23559]: 2021-03-13 02:51:47,278 INFO  Session:310 - Connected successfully!
Mar 13 02:51:46 soundpi1 java[23559]: 2021-03-13 02:51:46,595 TRACE Session:1367 - Session.Receiver stopped
Mar 13 02:51:46 soundpi1 java[23559]: 2021-03-13 02:51:46,595 TRACE Session:1367 - Session.Receiver stopped
Mar 13 02:51:46 soundpi1 java[23559]: 2021-03-13 02:51:46,594 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,579 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599614190, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,318 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599614054, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,196 DEBUG DealerClient:109 - Handled request. {key: b39c872a-bea1-4c0a-b386-34b57ea57e09, result: SUCCESS}
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,189 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,187 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: b39c872a-bea1-4c0a-b386-34b57ea57e09, pid: 691911367, sen>
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,061 DEBUG DealerClient:109 - Handled request. {key: 4688573e-dba6-48dd-85fd-54cfe25210d8, result: SUCCESS}
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,053 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:40:14 soundpi1 java[23559]: 2021-03-13 02:40:14,052 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 4688573e-dba6-48dd-85fd-54cfe25210d8, pid: 691911232, sen>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,888 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599613596, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,620 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599613103, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,602 DEBUG DealerClient:109 - Handled request. {key: 059ecb4c-4185-41dd-83ef-1260f74b431c, result: SUCCESS}
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,595 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,594 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 059ecb4c-4185-41dd-83ef-1260f74b431c, pid: 691910774, sen>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,340 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599613022, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,109 DEBUG DealerClient:109 - Handled request. {key: 3fb72830-372e-4fa1-ae67-e192a4851622, result: SUCCESS}
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,101 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,100 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 3fb72830-372e-4fa1-ae67-e192a4851622, pid: 691910280, sen>
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,028 DEBUG DealerClient:109 - Handled request. {key: 3d336877-ea05-4221-9614-205d51c5bdd2, result: SUCCESS}
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,020 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:40:13 soundpi1 java[23559]: 2021-03-13 02:40:13,019 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: 3d336877-ea05-4221-9614-205d51c5bdd2, pid: 691910193, sen>
Mar 13 02:39:08 soundpi1 java[23559]: 2021-03-13 02:39:08,460 INFO  DeviceStateHandler:249 - Put state. {ts: 1615599547828, connId: NGExM...DQTlD, reason: PLAYER_STATE_CHANGED, request: device { device_info { c>
Mar 13 02:39:08 soundpi1 java[23559]: 2021-03-13 02:39:08,125 DEBUG TokenProvider:55 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQB8DC...02k34I', >
Mar 13 02:39:08 soundpi1 java[23559]: 2021-03-13 02:39:08,124 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 5970, flags: 1, parts: 2
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,835 TRACE MercuryClient:140 - Send Mercury request, seq: 5970, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92>
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,835 DEBUG DealerClient:109 - Handled request. {key: ec24760f-c234-408f-9ade-4e928e1dbc9e, result: SUCCESS}
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,834 DEBUG TokenProvider:51 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: StoredToken{expiresIn=3600, accessToke>
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,826 DEBUG Player:293 - Received command: UpdateContext
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,825 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: ec24760f-c234-408f-9ade-4e928e1dbc9e, pid: 691845004, sen>
Mar 13 02:39:07 soundpi1 java[23559]: 2021-03-13 02:39:07,019 TRACE DeviceStateHandler:160 - Received cluster update at 1615599547011: cluster { timestamp: 1615599546716 active_device_id: "4a13ba38b9185d11d530c>
Mar 13 02:39:06 soundpi1 java[23559]: 2021-03-13 02:39:06,536 TRACE DeviceStateHandler:160 - Received cluster update at 1615599546528: cluster { timestamp: 1615599546235 active_device_id: "4a13ba38b9185d11d530c>
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,889 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,773 DEBUG Session:1338 - Received 0x10: 9CC035B05D5D5813C0F5822636DC1C3225CA7B19
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,659 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -8477159883362271232, uri: hm://pusher/v1/connections/NGExM2JhMzhiOTE4NWQxMWQ1MzBjM2>
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,659 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -8477159883362271232, flags: 1, parts: 1
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,657 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,555 INFO  Session:1362 - Skipping LegacyWelcome
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,554 TRACE Session:721 - Parsed product info: {remote-control=6, publish-activity=0, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incog>
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,545 INFO  Session:1324 - Received CountryCode: DE
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,544 INFO  Session:1334 - Received LicenseVersion: 0
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,544 INFO  Session:1362 - Skipping SecretBlock
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,540 INFO  Session:676 - Re-authenticated as 1158398333!
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,540 TRACE Session:1280 - Session.Receiver started
Mar 13 02:37:41 soundpi1 java[23559]: 2021-03-13 02:37:41,289 INFO  Session:310 - Connected successfully!
Mar 13 02:37:40 soundpi1 java[23559]: 2021-03-13 02:37:40,606 TRACE Session:1367 - Session.Receiver stopped
Mar 13 02:37:40 soundpi1 java[23559]: 2021-03-13 02:37:40,605 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,645 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,623 DEBUG Session:1338 - Received 0x10: 336F0695BC026D93BEE5B3673593C2B869F9AB18
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,601 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: 657555232410042368, uri: hm://pusher/v1/connections/NGExM2JhMzhiOTE4NWQxMWQ1MzBjM2U3>
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,601 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: 657555232410042368, flags: 1, parts: 1
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,587 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,586 INFO  Session:1362 - Skipping LegacyWelcome
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,586 TRACE Session:721 - Parsed product info: {remote-control=6, publish-activity=0, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incog>
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,579 INFO  Session:1324 - Received CountryCode: DE
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,579 INFO  Session:1334 - Received LicenseVersion: 0
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,579 INFO  Session:1362 - Skipping SecretBlock
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,577 INFO  Session:676 - Re-authenticated as 1158398333!
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,577 TRACE Session:1280 - Session.Receiver started
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,477 INFO  Session:310 - Connected successfully!
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,080 TRACE Session:1367 - Session.Receiver stopped
Mar 13 02:29:35 soundpi1 java[23559]: 2021-03-13 02:29:35,079 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,119 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,097 DEBUG Session:1338 - Received 0x10: 105C55DE2D10FB6ABC5C8A968176192714443942
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,076 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: 1829897410898296832, uri: hm://pusher/v1/connections/NGExM2JhMzhiOTE4NWQxMWQ1MzBjM2U>
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,076 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: 1829897410898296832, flags: 1, parts: 1
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,067 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,066 INFO  Session:1362 - Skipping LegacyWelcome
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,066 TRACE Session:721 - Parsed product info: {remote-control=6, publish-activity=0, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incog>
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,056 INFO  Session:1324 - Received CountryCode: DE
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,055 INFO  Session:1334 - Received LicenseVersion: 0
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,055 INFO  Session:1362 - Skipping SecretBlock
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,052 INFO  Session:676 - Re-authenticated as 1158398333!
Mar 13 02:21:30 soundpi1 java[23559]: 2021-03-13 02:21:30,052 TRACE Session:1280 - Session.Receiver started
Mar 13 02:21:29 soundpi1 java[23559]: 2021-03-13 02:21:29,989 INFO  Session:310 - Connected successfully!
Mar 13 02:21:29 soundpi1 java[23559]: 2021-03-13 02:21:29,593 TRACE Session:1367 - Session.Receiver stopped
Mar 13 02:21:29 soundpi1 java[23559]: 2021-03-13 02:21:29,592 WARN  Session:1307 - Socket timed out. Reconnecting...

Version/Commit Release 1.5.4

devgianlu commented 3 years ago

That definitely shouldn't happen, mainly because there are ping/pongs going every two minutes. I am also not experiencing this playing music for 8+ hours straight.

Did you make any change to the surrounding environment? Something that might be shutting down long last connections perhaps?

Also the music shouldn't stop while reconnecting, but that's another issue.

paulbastian commented 3 years ago

Ok, it seems even in idle, its disconnecting and reconnecting right now in regular 8 minutes and 5 seconds intervals:

Mar 14 18:11:31 soundpi1 java[13712]: 2021-03-14 18:11:31,243 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,583 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,464 DEBUG Session:1338 - Received 0x10: 27C9CF3367B8F33EED029FD01721654D1B7329D4
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,346 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -3909359772045934592, uri: hm://pusher/v1/connections/NzkxNDM5OGQyZWE2Y2NlNDhmZDYzYj>
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,345 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -3909359772045934592, flags: 1, parts: 1
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,239 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,236 INFO  Session:1362 - Skipping LegacyWelcome
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,236 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=21>
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,230 INFO  Session:1324 - Received CountryCode: DE
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,229 INFO  Session:1334 - Received LicenseVersion: 0
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,227 INFO  Session:1362 - Skipping SecretBlock
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,225 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Mar 14 18:03:26 soundpi1 java[13712]: 2021-03-14 18:03:26,225 TRACE Session:1280 - Session.Receiver started
Mar 14 18:03:25 soundpi1 java[13712]: 2021-03-14 18:03:25,962 INFO  Session:310 - Connected successfully!
Mar 14 18:03:25 soundpi1 java[13712]: 2021-03-14 18:03:25,244 TRACE Session:1367 - Session.Receiver stopped
Mar 14 18:03:25 soundpi1 java[13712]: 2021-03-14 18:03:25,243 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,286 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,264 DEBUG Session:1338 - Received 0x10: 4DDE98652008A214710CC916CBBE0B1D0C6164AD
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,231 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,230 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -2178295262345166848, uri: hm://pusher/v1/connections/NzkxNDM5OGQyZWE2Y2NlNDhmZDYzYj>
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,230 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -2178295262345166848, flags: 1, parts: 1
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,229 INFO  Session:1362 - Skipping LegacyWelcome
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,229 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=21>
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,221 INFO  Session:1324 - Received CountryCode: DE
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,220 INFO  Session:1334 - Received LicenseVersion: 0
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,220 INFO  Session:1362 - Skipping SecretBlock
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,218 TRACE Session:1280 - Session.Receiver started
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,218 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Mar 14 17:55:20 soundpi1 java[13712]: 2021-03-14 17:55:20,143 INFO  Session:310 - Connected successfully!
Mar 14 17:55:19 soundpi1 java[13712]: 2021-03-14 17:55:19,729 TRACE Session:1367 - Session.Receiver stopped
Mar 14 17:55:19 soundpi1 java[13712]: 2021-03-14 17:55:19,728 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 14 17:47:15 soundpi1 java[13712]: 2021-03-14 17:47:15,058 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,942 DEBUG Session:1338 - Received 0x10: 25D334FEF41565983FDFDC59D813C640DEEAFD0C
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,826 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: 3674982375911063552, uri: hm://pusher/v1/connections/NzkxNDM5OGQyZWE2Y2NlNDhmZDYzYjR>
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,825 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: 3674982375911063552, flags: 1, parts: 1
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,722 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,719 INFO  Session:1362 - Skipping LegacyWelcome
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,719 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=21>
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,713 INFO  Session:1324 - Received CountryCode: DE
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,712 INFO  Session:1334 - Received LicenseVersion: 0
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,710 INFO  Session:1362 - Skipping SecretBlock
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,707 TRACE Session:1280 - Session.Receiver started
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,707 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Mar 14 17:47:14 soundpi1 java[13712]: 2021-03-14 17:47:14,448 INFO  Session:310 - Connected successfully!
Mar 14 17:47:13 soundpi1 java[13712]: 2021-03-14 17:47:13,754 TRACE Session:1367 - Session.Receiver stopped
Mar 14 17:47:13 soundpi1 java[13712]: 2021-03-14 17:47:13,753 WARN  Session:1307 - Socket timed out. Reconnecting...
Mar 14 17:39:09 soundpi1 java[13712]: 2021-03-14 17:39:09,085 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,966 DEBUG Session:1338 - Received 0x10: E59599A04C78718ED4DEA69B5798B8BE8A5D6D91
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,848 INFO  Session:1362 - Skipping UnknownData_AllZeros
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,847 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -2479770355565068288, uri: hm://pusher/v1/connections/NzkxNDM5OGQyZWE2Y2NlNDhmZDYzYj>
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,846 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -2479770355565068288, flags: 1, parts: 1
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,734 INFO  Session:1362 - Skipping LegacyWelcome
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,734 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=21>
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,725 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,727 INFO  Session:1324 - Received CountryCode: DE
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,727 INFO  Session:1334 - Received LicenseVersion: 0
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,726 INFO  Session:1362 - Skipping SecretBlock
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,725 TRACE Session:1280 - Session.Receiver started
Mar 14 17:39:08 soundpi1 java[13712]: 2021-03-14 17:39:08,429 INFO  Session:310 - Connected successfully!
Mar 14 17:39:07 soundpi1 java[13712]: 2021-03-14 17:39:07,699 TRACE Session:1367 - Session.Receiver stopped
Mar 14 17:39:07 soundpi1 java[13712]: 2021-03-14 17:39:07,698 WARN  Session:1307 - Socket timed out. Reconnecting...

This still seems to be successful in almost 100%cases It might be related to the raspberry pi, as this might be the same cause why many people have trouble with librespot whihc doesnt handle reconnects Do you know anything that might cause the timeout? Anyhting that might be related to 485 seconds?

frodeseverin commented 3 years ago

I have also experienced a disconnect at 30 minutes when playing a track that was longer. Some Norwegian Folk Tales are available on Spotify, i.e. Asbjornsen og Moe. Some of these tracks are longer than 30 minutes.

I can try to reproduce on latest Git version if needed.

;)Frode

devgianlu commented 3 years ago

Sorry for the big delay. Upon further inspecting the logs it looks like only the first occasion you report was caused by a network failure. The others report a Socket timed out. Reconnecting... message that comes from the pong listener: this doesn't necessarily mean that the connection was broken, but that the ping was at least 5 seconds delayed.

That might have possibly been an issue with their server, but I don't think they changed the ping/pongs frequency as it's still fine for me. Are you still experiencing this issue?

The 30 minutes issue is different since it may have triggered by any of the network layers between you and the Spotify server. A tcp dump would be helpful in that case, but I don't want to ask too much. The logs don't say which AP server you were connected to, that could be helpful to determine whether it's a faulty server.

@paulbastian @frodeseverin

paulbastian commented 3 years ago

Hi, sorry for the delay. I got a tcpdump of the regular disconnects. So this is what the log looks like:

Apr 11 11:44:57 soundpi1 java[315]: 2021-04-11 11:44:57,370 TRACE DeviceStateHandler:160 - Received cluster update at 1618134297359: cluster { timestamp: 1618134297267 active_device_id: "2ec405d5b6c6bec81b9a789>
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,352 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,328 DEBUG Session:1338 - Received 0x10: A1D161A7CE4F83B695FC7F9658E65E59CFBC2FEB
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,309 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -2296248670749720576, uri: hm://pusher/v1/connections/MjdhM2Y4MDczNDFlNzkwOTVkNzdkYmZk>
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,309 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -2296248670749720576, flags: 1, parts: 1
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,308 INFO  Session:1362 - Skipping UnknownData_AllZeros
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,308 INFO  Session:1362 - Skipping LegacyWelcome
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,307 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=2160>
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,283 INFO  Session:1324 - Received CountryCode: DE
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,282 INFO  Session:1334 - Received LicenseVersion: 0
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,281 INFO  Session:1362 - Skipping SecretBlock
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,279 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,279 TRACE Session:1280 - Session.Receiver started
Apr 11 11:44:11 soundpi1 java[315]: 2021-04-11 11:44:11,209 INFO  Session:310 - Connected successfully!
Apr 11 11:44:10 soundpi1 java[315]: 2021-04-11 11:44:10,801 TRACE Session:1367 - Session.Receiver stopped
Apr 11 11:44:10 soundpi1 java[315]: 2021-04-11 11:44:10,800 WARN  Session:1307 - Socket timed out. Reconnecting...
Apr 11 11:40:26 soundpi1 java[315]: 2021-04-11 11:40:26,441 TRACE DeviceStateHandler:160 - Received cluster update at 1618134026433: cluster { timestamp: 1618134026332 active_device_id: "2ec405d5b6c6bec81b9a789>
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,841 INFO  Session:1289 - Skipping unknown command {cmd: 0x75, payload: 000000}
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,818 DEBUG Session:1338 - Received 0x10: 1AFED4AE25A6851AE9AB4C065D1442AC3EC0A8F2
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,801 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: 6108613925039767552, uri: hm://pusher/v1/connections/MjdhM2Y4MDczNDFlNzkwOTVkNzdkYmZkO>
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,800 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: 6108613925039767552, flags: 1, parts: 1
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,799 INFO  Session:1362 - Skipping UnknownData_AllZeros
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,799 INFO  Session:1362 - Skipping LegacyWelcome
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,798 TRACE Session:721 - Parsed product info: {remote-control=6, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=2160>
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,776 INFO  Session:1324 - Received CountryCode: DE
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,775 INFO  Session:1334 - Received LicenseVersion: 0
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,774 INFO  Session:1362 - Skipping SecretBlock
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,774 INFO  Session:676 - Re-authenticated as wamvxztrfpcomxphv6401as55!
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,772 TRACE Session:1280 - Session.Receiver started
Apr 11 11:36:05 soundpi1 java[315]: 2021-04-11 11:36:05,706 INFO  Session:310 - Connected successfully!

and this is the matching tcpdump:

11:44:08.498382 IP soundpi1.36974 > 44.224.186.35.bc.googleusercontent.com.https: Flags [P.], seq 3304:3363, ack 39367, win 1086, options [nop,nop,TS val 1371831563 ecr 255756746], length 59
11:44:08.508519 IP 44.224.186.35.bc.googleusercontent.com.https > soundpi1.36974: Flags [.], ack 3363, win 272, options [nop,nop,TS val 255786639 ecr 1371831563], length 0
11:44:08.615697 IP 44.224.186.35.bc.googleusercontent.com.https > soundpi1.36974: Flags [P.], seq 39367:39407, ack 3363, win 272, options [nop,nop,TS val 255786746 ecr 1371831563], length 40
11:44:08.615729 IP soundpi1.36974 > 44.224.186.35.bc.googleusercontent.com.https: Flags [.], ack 39407, win 1086, options [nop,nop,TS val 1371831680 ecr 255786746], length 0
11:44:09.974441 IP6 _gateway > ff02::1: ICMP6, neighbor advertisement, tgt is _gateway, length 32
11:44:10.800942 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8545120 ecr 4156495240], length 0
11:44:10.802940 IP soundpi1.41907 > _gateway.domain: 42891+ [1au] AAAA? gew1-accesspoint-e-dgwk.ap.spotify.com. (67)
11:44:10.803363 IP soundpi1.53512 > _gateway.domain: 53879+ [1au] A? gew1-accesspoint-e-dgwk.ap.spotify.com. (67)
11:44:10.811339 ARP, Request who-has soundpi1 tell _gateway, length 46
11:44:10.811370 ARP, Reply soundpi1 is-at dc:a6:32:3c:09:8d (oui Unknown), length 28
11:44:10.811514 IP _gateway.domain > soundpi1.41907: 42891 0/1/1 (117)
11:44:10.813905 IP _gateway.domain > soundpi1.53512: 53879 1/0/1 A 104.199.65.59 (83)
11:44:10.815171 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [S], seq 1774687137, win 64240, options [mss 1460,sackOK,TS val 3058490903 ecr 0,nop,wscale 7], length 0
11:44:10.838821 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [S.], seq 3291170758, ack 1774687138, win 65084, options [mss 1240,sackOK,TS val 1870044678 ecr 3058490903,nop,wscale 12], length 0
11:44:10.838877 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 1, win 502, options [nop,nop,TS val 3058490926 ecr 1870044678], length 0
11:44:10.839612 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 1:2, ack 1, win 502, options [nop,nop,TS val 3058490927 ecr 1870044678], length 1
11:44:10.862821 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 2, win 16, options [nop,nop,TS val 1870044702 ecr 3058490927], length 0
11:44:10.862863 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 2:155, ack 1, win 502, options [nop,nop,TS val 3058490950 ecr 1870044702], length 153
11:44:10.886326 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 155, win 16, options [nop,nop,TS val 1870044726 ecr 3058490950], length 0
11:44:10.886691 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 1:458, ack 155, win 16, options [nop,nop,TS val 1870044726 ecr 3058490950], length 457
11:44:10.886712 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 458, win 501, options [nop,nop,TS val 3058490974 ecr 1870044726], length 0
11:44:10.908856 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 155:156, ack 458, win 501, options [nop,nop,TS val 3058490996 ecr 1870044726], length 1
11:44:10.932262 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 156, win 16, options [nop,nop,TS val 1870044772 ecr 3058490996], length 0
11:44:10.932284 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 156:191, ack 458, win 501, options [nop,nop,TS val 3058491020 ecr 1870044772], length 35
11:44:10.955515 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 191, win 16, options [nop,nop,TS val 1870044795 ecr 3058491020], length 0
11:44:11.033114 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8545353 ecr 4156495240], length 0
11:44:11.211945 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 191:507, ack 458, win 501, options [nop,nop,TS val 3058491299 ecr 1870044795], length 316
11:44:11.235377 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 507, win 16, options [nop,nop,TS val 1870045075 ecr 3058491299], length 0
11:44:11.235415 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 507:511, ack 458, win 501, options [nop,nop,TS val 3058491323 ecr 1870045075], length 4
11:44:11.258881 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 511, win 16, options [nop,nop,TS val 1870045098 ecr 3058491323], length 0
11:44:11.273117 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8545593 ecr 4156495240], length 0
11:44:11.277545 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], seq 458:1686, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 1228
11:44:11.277568 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 1686, win 501, options [nop,nop,TS val 3058491365 ecr 1870045117], length 0
11:44:11.278124 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 1686:2914, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 1228
11:44:11.278158 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 2914, win 493, options [nop,nop,TS val 3058491366 ecr 1870045117], length 0
11:44:11.278319 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], seq 2914:4142, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 1228
11:44:11.278341 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 4142, win 484, options [nop,nop,TS val 3058491366 ecr 1870045117], length 0
11:44:11.278490 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 4142:5370, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 1228
11:44:11.278517 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 5370, win 475, options [nop,nop,TS val 3058491366 ecr 1870045117], length 0
11:44:11.278690 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 511:534, ack 5370, win 475, options [nop,nop,TS val 3058491366 ecr 1870045117], length 23
11:44:11.279564 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], seq 5370:6598, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 1228
11:44:11.279628 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 6598, win 466, options [nop,nop,TS val 3058491367 ecr 1870045117], length 0
11:44:11.279723 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 6598:7485, ack 511, win 16, options [nop,nop,TS val 1870045117 ecr 3058491323], length 887
11:44:11.279773 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 7485, win 460, options [nop,nop,TS val 3058491367 ecr 1870045117], length 0
11:44:11.303664 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [.], ack 534, win 16, options [nop,nop,TS val 1870045143 ecr 3058491366], length 0
11:44:11.303733 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [P.], seq 534:579, ack 7485, win 460, options [nop,nop,TS val 3058491391 ecr 1870045143], length 45
11:44:11.304312 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 7485:8005, ack 534, win 16, options [nop,nop,TS val 1870045143 ecr 3058491367], length 520
11:44:11.304336 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 8005, win 456, options [nop,nop,TS val 3058491392 ecr 1870045143], length 0
11:44:11.327834 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 8005:8043, ack 579, win 16, options [nop,nop,TS val 1870045167 ecr 3058491391], length 38
11:44:11.327865 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 8043, win 501, options [nop,nop,TS val 3058491415 ecr 1870045167], length 0
11:44:11.351287 IP 59.65.199.104.bc.googleusercontent.com.https > soundpi1.55410: Flags [P.], seq 8043:8053, ack 579, win 16, options [nop,nop,TS val 1870045191 ecr 3058491415], length 10
11:44:11.351325 IP soundpi1.55410 > 59.65.199.104.bc.googleusercontent.com.https: Flags [.], ack 8053, win 501, options [nop,nop,TS val 3058491439 ecr 1870045191], length 0
11:44:11.743131 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8546063 ecr 4156495240], length 0
11:44:12.723117 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8547043 ecr 4156495240], length 0

I can see that I am connected to aa diffrent google cloud service afterwards. I can send you the full dump if that helps. Best regards, Paul

devgianlu commented 3 years ago

The reconnection is made to a different host because it's randomly picked from a list. The dump looks completely fine and now I wonder whether we should be wait more before deciding that the connection hang up.

I have made the "reconnection" timeout configurable (the default is now 10 seconds instead of 5). You can play around with that value and see if the problem disappears, but I think everything more than 30 seconds means there's something else wrong.

paulbastian commented 3 years ago

Ok, so I looked at it again. The line which prints the warning is Apr 11 11:44:10 soundpi1 java[315]: 2021-04-11 11:44:10,800 WARN Session:1307 - Socket timed out. Reconnecting... so at 11:44:10:800 and this equals to 11:44:10.800942 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [F.], seq 612, ack 8161, win 501, options [nop,nop,TS val 8545120 ecr 4156495240], length 0 in the TCP dump, where the F flag signalizes the closing of the connection.

the other lines above are actually for a different connection and don't relate. I've looked backwards through the dump and the last traffic on the port was:

11:42:05.799402 IP 69.64.199.104.bc.googleusercontent.com.https > soundpi1.45112: Flags [P.], seq 8139:8150, ack 601, win 16, options [nop,nop,TS val 4156495196 ecr 8300153], length 11
11:42:05.799446 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [.], ack 8150, win 501, options [nop,nop,TS val 8420119 ecr 4156495196], length 0
11:42:05.800055 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [P.], seq 601:608, ack 8150, win 501, options [nop,nop,TS val 8420119 ecr 4156495196], length 7
11:42:05.821703 IP 69.64.199.104.bc.googleusercontent.com.https > soundpi1.45112: Flags [.], ack 608, win 16, options [nop,nop,TS val 4156495218 ecr 8420119], length 0
11:42:05.821735 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [P.], seq 608:612, ack 8150, win 501, options [nop,nop,TS val 8420141 ecr 4156495218], length 4
11:42:05.843323 IP 69.64.199.104.bc.googleusercontent.com.https > soundpi1.45112: Flags [.], ack 612, win 16, options [nop,nop,TS val 4156495239 ecr 8420141], length 0
11:42:05.844004 IP 69.64.199.104.bc.googleusercontent.com.https > soundpi1.45112: Flags [P.], seq 8150:8161, ack 612, win 16, options [nop,nop,TS val 4156495240 ecr 8420141], length 11
11:42:05.844023 IP soundpi1.45112 > 69.64.199.104.bc.googleusercontent.com.https: Flags [.], ack 8161, win 501, options [nop,nop,TS val 8420163 ecr 4156495240], length 0

which looks pretty legitimate? Why is my side sending FIN flag then?

paulbastian commented 3 years ago

Ok, I can see spotify server is initiating traffic every 2 minutes before this at 11:38:05, 11:40:05 and 11:42:05 Then nothing arrives at 11:44:05 and the 5 seconds timeout kicks in and at 11:44:10 my side closes the connection.

devgianlu commented 3 years ago

Exactly. The fact it decides not to send anything is unusal. You can try making the timeout a lot higher with connectionTimeout in the configs and see on the dump whether the server eventually sends some more bytes or not.

paulbastian commented 3 years ago

I have checked running the same version of librespot-java on my laptop, I see in the tcpdump a connection every 30 seconds, 2push&2ack's, but this time its initiated by the librespot client. How come such a diffrent behaviour on my raspberry pi and my laptop?

devgianlu commented 3 years ago

I am pretty confident that is impossible: we are listening for Ping events and sending a Pong back. The server will then respond with a PongAck which we just discard.

You might be seeing some other data being transferred.

paulbastian commented 3 years ago

Do you have some example data what the trace looks like at your setup? But I probably don't have the time to investigate too much in the near future :/

devgianlu commented 3 years ago 
16:26:35.558122 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [P.], seq 50:100, ack 48, win 331, options [nop,nop,TS val 69224530 ecr 2382895804], length 50
16:26:35.576842 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [.], ack 100, win 266, options [nop,nop,TS val 2382925540 ecr 69224530], length 0
16:26:35.844235 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [P.], seq 48:95, ack 100, win 266, options [nop,nop,TS val 2382925806 ecr 69224530], length 47
16:26:35.844483 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [.], ack 95, win 331, options [nop,nop,TS val 69224558 ecr 2382925806], length 0

16:27:05.558147 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [P.], seq 100:150, ack 95, win 331, options [nop,nop,TS val 69227530 ecr 2382925806], length 50
16:27:05.574367 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [.], ack 150, win 266, options [nop,nop,TS val 2382955537 ecr 69227530], length 0
16:27:05.841785 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [P.], seq 95:142, ack 150, win 266, options [nop,nop,TS val 2382955804 ecr 69227530], length 47
16:27:05.842023 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [.], ack 142, win 331, options [nop,nop,TS val 69227558 ecr 2382955804], length 0

16:27:35.558111 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [P.], seq 150:200, ack 142, win 331, options [nop,nop,TS val 69230530 ecr 2382955804], length 50
16:27:35.576875 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [.], ack 200, win 266, options [nop,nop,TS val 2382985537 ecr 69230530], length 0
16:27:35.846861 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [P.], seq 142:189, ack 200, win 266, options [nop,nop,TS val 2382985803 ecr 69230530], length 47
16:27:35.847138 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [.], ack 189, win 331, options [nop,nop,TS val 69230559 ecr 2382985803], length 0

16:28:05.558130 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [P.], seq 200:250, ack 189, win 331, options [nop,nop,TS val 69233530 ecr 2382985803], length 50
16:28:05.574288 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [.], ack 250, win 266, options [nop,nop,TS val 2383015538 ecr 69233530], length 0
16:28:05.841768 IP 46.224.186.35.bc.googleusercontent.com.https > server.42251: Flags [P.], seq 189:236, ack 250, win 266, options [nop,nop,TS val 2383015804 ecr 69233530], length 47
16:28:05.842014 IP server.42251 > 46.224.186.35.bc.googleusercontent.com.https: Flags [.], ack 236, win 331, options [nop,nop,TS val 69233558 ecr 2383015804], length 0

Here's some I captured.

vincenttermaat commented 3 years ago

I also get frequent disconnects, as described. But I don't know where I can find/enable the logs. On Windows 10, running the player.jar via javaw.

How do I get to these logs?

devgianlu commented 3 years ago

How do I get to these logs?

You can see the librespot-java logs by using java instead of javaw for launching the app. The other "logs" are the output from tcpdump.

Ristovski commented 2 years ago

I used to experience this issue with NTP sync enabled, setting the following config options fixed it, might be worth a try:

[time]
    manualCorrection = 0
    synchronizationMethod = "MANUAL"
paulbastian commented 2 years ago

@Ristovski where is this configured?

paulbastian commented 2 years ago

ok found it I will test it in the next days

paulbastian commented 2 years ago

no change for me :/ socket timeout still happening

KagChi commented 2 years ago

I have same issue, not even 3 minutes the session always reconnect.