search

jellyfin / jellyfin-web

Web Client for Jellyfin
https://jellyfin.org
GNU General Public License v2.0
2.27k stars 1.2k forks source link

Syncplay sessions close after playing video for 30 seconds #5485

Closed soultaco83 closed 3 months ago

soultaco83 commented 4 months ago

Please describe your bug

Moving from https://github.com/jellyfin/jellyfin-web/issues/5446 When playing video from a syncplay session. The Sessions will close and stop playing

Reproduction Steps

1: Start a syncplay session 2: Play any video file 3: Wait 30 seconds 4: Stream crashes and backs to previous page

Jellyfin Version

Unstable (master branch)

if other:

No response

Environment

- OS: Unraid
- Linux Kernel: Linux 6.7.12-Unraid x86_64
- Virtualization: Docker
- Clients: Browser
- Browser: Chrome, Firefox, Edge
- FFmpeg Version: 6.0.1-6
- Playback Method: Doesn't seem to be related
- Hardware Acceleration: QSV
- GPU Model: Arc A770
- Reverse Proxy: n/a
- Base URL: n/a

Jellyfin logs

Attached below are server logs and snippet of console
Debug enabled

-05-09 03:18:31.074 -04:00] [DBG] [21] Jellyfin.Api.Auth.CustomAuthenticationHandler: AuthenticationScheme: "CustomAuthentication" was successfully authenticated.
[2024-05-09 03:18:31.083 -04:00] [INF] [21] Emby.Server.Implementations.SyncPlay.Group: Session "167f9f73419f326929282b1271a2ff32" requested Play in group "0210dd87-f79b-4b5a-9f5e-697e852764cc" that is Idle.
[2024-05-09 03:18:31.083 -04:00] [INF] [21] Emby.Server.Implementations.SyncPlay.Group: Group "0210dd87-f79b-4b5a-9f5e-697e852764cc" switching from Idle to Waiting.
[2024-05-09 03:18:31.085 -04:00] [DBG] [21] MediaBrowser.Controller.Entities.BaseItem: "test" has no parental rating set.

...

[2024-05-09 03:18:31.102 -04:00] [DBG] [21] MediaBrowser.Controller.SyncPlay.GroupStates.WaitingGroupState: Session "167f9f73419f326929282b1271a2ff32" set a new play queue in group "0210dd87-f79b-4b5a-9f5e-697e852764cc".

...


[2024-05-09 03:19:04.272 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: PingTranscodingJob PlaySessionId="f65f00d9b9204b0a956bf4d62f84394b" isUsedPaused: False
[2024-05-09 03:19:05.272 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: PingTranscodingJob PlaySessionId="f65f00d9b9204b0a956bf4d62f84394b" isUsedPaused: False
[2024-05-09 03:19:05.574 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef12-1.mp4"
[2024-05-09 03:19:05.574 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef120.mp4"
[2024-05-09 03:19:05.574 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef121.mp4"
[2024-05-09 03:19:05.575 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef122.mp4"
[2024-05-09 03:19:05.575 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef123.mp4"
[2024-05-09 03:19:05.576 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef124.mp4"
[2024-05-09 03:19:05.576 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef125.mp4"
[2024-05-09 03:19:05.577 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef126.mp4"
[2024-05-09 03:19:05.577 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef127.mp4"
[2024-05-09 03:19:05.577 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef128.mp4"
[2024-05-09 03:19:05.577 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef129.mp4"
[2024-05-09 03:19:05.578 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1210.mp4"
[2024-05-09 03:19:05.578 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1211.mp4"
[2024-05-09 03:19:05.579 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1212.mp4"
[2024-05-09 03:19:05.579 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1213.mp4"
[2024-05-09 03:19:05.580 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1214.mp4"
[2024-05-09 03:19:05.580 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1215.mp4"
[2024-05-09 03:19:05.580 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1216.mp4"
[2024-05-09 03:19:05.581 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1217.mp4"
[2024-05-09 03:19:05.581 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1218.mp4"
[2024-05-09 03:19:05.581 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1219.mp4"
[2024-05-09 03:19:05.582 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1220.mp4"
[2024-05-09 03:19:05.582 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1221.mp4"
[2024-05-09 03:19:05.582 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1222.mp4"
[2024-05-09 03:19:05.583 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1223.mp4"
[2024-05-09 03:19:05.584 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1224.mp4"
[2024-05-09 03:19:05.584 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1225.mp4"
[2024-05-09 03:19:05.584 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1226.mp4"
[2024-05-09 03:19:05.584 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1227.mp4"
[2024-05-09 03:19:05.585 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1228.mp4"
[2024-05-09 03:19:05.585 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1229.mp4"
[2024-05-09 03:19:05.585 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1230.mp4"
[2024-05-09 03:19:05.585 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef1231.mp4"
[2024-05-09 03:19:05.585 -04:00] [DBG] [10] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting HLS file "/transcodes/bd091fbc4f17ec8aca4768956042ef12.m3u8"
[2024-05-09 03:19:05.589 -04:00] [INF] [10] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Jellyfin Web" "10.9.0" playing "Undertaker". Stopped at "29724" ms
[2024-05-09 03:19:05.599 -04:00] [DBG] [10] Jellyfin.Api.Middleware.ResponseTimeMiddleware: Slow HTTP Response from "http://10.10.10.23:8096/Sessions/Playing/Stopped" to "192.168.108.170" in 0:00:01.5857745 with Status Code 204
[2024-05-09 03:19:07.113 -04:00] [DBG] [14] Emby.Server.Implementations.Session.SessionWebSocketListener: Watching 1 WebSockets.

### FFmpeg logs

```shell
Not a hardware transcode issue

Please attach any browser or client logs here

log_20240509.log

FFmpeg.Remux-2024-05-09_03-29-11_394aef7aa8fdf3830840f9d598a199d3_11a3f9c7.log FFmpeg.Remux-2024-05-09_03-29-52_394aef7aa8fdf3830840f9d598a199d3_612a87ea.log

Please attach any screenshots here

image

Code of Conduct

jellyfin-bot commented 4 months ago

Hi, it seems like your issue report has the following item(s) that need to be addressed:

This is an automated message, currently under testing. Please file an issue here if you encounter any problems.

TIITANIC1912 commented 3 months ago

Hello.

Same thing here with Jellyfin Server 10.9.0.0 in Debian 12, in a VM with the latest package from the jellyfin repo 10.9.0+deb12. it works a bit better before the update.

poulpor commented 3 months ago

Same here too with Jellyfin Server 10.9.0 latest stable, on a Synology (DSM 7.2.1-69057 Update 4), didn't have this strange behavior with 10.8.13. Tried with and without hardware transcoding, same result, syncplay closes after 30 secondes on both computers and return to previous page.

TimGels commented 3 months ago

I am able to reproduce this behavior on current master (latest commit 25c23af8659700909995ca9c91c5dafccc6d348b) and latest web master (latest commit b40cbb2b97268011bc2ebdf2aff74dec55b43921).

afbeelding

thornbill commented 3 months ago

The error message in web is that the api request reporting the playback start times out and I don't see anything in the provided server logs indicating why... server logs of the failed request would likely give some details as to cause of the issue.

TimGels commented 3 months ago

I am not seeing anything weird with a quick glance on the terminal output of visual studio of the server when this problem occurs.

[18:03:44] [INF] [39] Emby.Server.Implementations.SyncPlay.Group: Session 2ab1b5d58aa78b0eff5aaf44cfb9179f requested IgnoreWait in group 1a871bf4-f845-4e16-a316-92000eef541e that is Waiting.
[18:03:44] [INF] [23] MediaBrowser.Controller.MediaEncoding.TranscodingJob: Stopping ffmpeg process with q command for C:\Users\Tim\AppData\Local\jellyfin\cache\transcodes\cc3c2e1bf77f00eeb3d2f487fa629cb8.m3u8
[18:03:44] [INF] [39] MediaBrowser.Controller.MediaEncoding.TranscodingJob: Stopping ffmpeg process with q command for C:\Users\Tim\AppData\Local\jellyfin\cache\transcodes\ad5c48a15455f427854b21d31c9c7513.m3u8
[18:03:44] [INF] [40] Emby.Server.Implementations.SyncPlay.Group: Session a0338c7db866e181c8763d7f052d56d1 requested IgnoreWait in group 1a871bf4-f845-4e16-a316-92000eef541e that is Waiting.
[18:03:44] [INF] [40] Emby.Server.Implementations.SyncPlay.Group: Group 1a871bf4-f845-4e16-a316-92000eef541e switching from Waiting to Playing.
[18:03:44] [INF] [23] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: FFmpeg exited with code 0
[18:03:44] [INF] [23] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting partial stream file(s) C:\Users\Tim\AppData\Local\jellyfin\cache\transcodes\cc3c2e1bf77f00eeb3d2f487fa629cb8.m3u8
[18:03:44] [INF] [39] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: FFmpeg exited with code 0
[18:03:44] [INF] [39] MediaBrowser.MediaEncoding.Transcoding.TranscodeManager: Deleting partial stream file(s) C:\Users\Tim\AppData\Local\jellyfin\cache\transcodes\ad5c48a15455f427854b21d31c9c7513.m3u8
[18:03:45] [INF] [22] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Web 10.10.0 playing The Red-Nosed Reindeer. Stopped at 29694 ms
[18:03:46] [INF] [39] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Web 10.10.0 playing The Red-Nosed Reindeer. Stopped at 29689 ms

Will continue looking into it what might be going wrong.

thornbill commented 3 months ago

Any failed requests in the browser's network tab?

TimGels commented 3 months ago

Any failed requests in the browser's network tab?

None failed in the browser network log: afbeelding

TimGels commented 3 months ago

I am still unsure what endpoint it calls where it times out on. Does it even call one?

thornbill commented 3 months ago

Oh good call... I thought this was related to a progress reporting request, but it could just be events within web. 🤔

TimGels commented 3 months ago

It looks like it times out on line 170 (QueueCore.js). It times out on the default configured 30s WaitForEventDefaultTimeout timeout located in Helper.js afbeelding

PeachesMLG commented 3 months ago

I think this is just a race condition, from what I can tell the playbackstart event is being called here, however from spamming a bunch of logs everywhere, it looks like it gets called before we run the code to wait for the event

PeachesMLG commented 3 months ago

https://github.com/jellyfin/jellyfin-web/blob/master/src/plugins/syncPlay/core/QueueCore.js#L237

So moving this.scheduleReadyRequestOnPlaybackStart above playerWrapper.localPlay does fix this issue, but I dont really know the code well enough to know if there are any side effects to this or not. But its definatly just a case of the event being called before we start listening to it

TimGels commented 3 months ago

Amazing find. Perhaps someone from web knows if that is a good way to fix it.

thornbill commented 3 months ago

Nice find... this seems like one of those things that should have never worked. Clearly you should register the event listener before starting playback. 🤔🤷‍♂️

PeachesMLG commented 3 months ago

Looks like this commit broke it: https://github.com/jellyfin/jellyfin-web/commit/1b2c99a4eca58c7f468ea9454a5a7c1127bcafd9

PeachesMLG commented 3 months ago

So Ive been looking at this for a while, and I have no idea why that commit broke anything, from what I can see it should be executing the exact same code, but for some reason it changes the timing order of things.

But Ive decided its just magic, so ive raised a pr to revert the refactor, if anyone wants to investigate into why the refactor broke stuff feel free to close my pr and open your own

soultaco83 commented 3 months ago

@PeachesMLG I cloned the jellyfin-web repo and built the web interface with your changes to the playbackmanager.js file. Restarted the server after install. I am still failing at the 30 second mark. 10.10.10.20-1715654232556.log playbackmanager.txt changed to txt for upload

PeachesMLG commented 3 months ago

Oh, weird. so I ran it locally again, and it worked fine, so I did a few more tests and again everything was working fine. However on the 5th attempt it broke.

At a guess we are running two async tasks in parralel when they need to be waiting on one another... (which is probabbly why my fix "worked" since it changed the timings a few fractions of a milliseconds?)

Let me investigate this further...

TimGels commented 3 months ago

Maybe it is a good idea to mention something in the pull request on why it's closed. Can even be just a link to your comment.

PeachesMLG commented 3 months ago

So from what I can see by spamming a bunch of logs everywhere, the promise somehow gets released here:

https://github.com/jellyfin/jellyfin-web/blob/master/src/components/playback/playbackmanager.js#L478

So the scheduleReadyRequestOnPlaybackStart method gets released and runs before it should (Which in this case is good because it should be called before the event anyways)

I think my original suggestion of moving the scheduleReadyRequestOnPlaybackStart above the playerWrapper.localPlay is the best option here, the only issue is that two playbackstart events are triggered, so im not sure if thats going to cause any issues (potentially we want to wait for the second one?)

Javascript isnt really my forte and I dont know this codebase that well, so ill leave this for somone smarter to do, but id be interested in seeing what the fix ends up being

dmitrylyzo commented 3 months ago

The "magic" is that my PR has bound apiClient.getEndpointInfo and playAfterBitrateDetect promises to play call. This way the playback start becomes "sync", allowing to wait for success or error. A side effect is that the scheduleReadyRequestOnPlaybackStart call now waits for the play (localPlay) promise to be resolved , which is too late.

I think my original suggestion of moving the scheduleReadyRequestOnPlaybackStart above the playerWrapper.localPlay is the best option here

This is actually the correct way to handle events. As Bill said, subscribe before performing an action that might trigger an event. The only question is how to stop waiting for playbackstart in case of an error?

the only issue is that two playbackstart events are triggered

From the same object? playbackstart is triggered from 3 different objects:

PeachesMLG commented 3 months ago

No idea about what object they originate from, but if you look in dev console it triggers two events image

dmitrylyzo commented 3 months ago

No idea about what object they originate from, but if you look in dev console it triggers two events image

These are the handlers. Look to the right where these lines are coming from. I guess:

  1. onPlaybackStart from components/nowPlayingBar.
  2. onStateChanged from components/nowPlayingBar.
  3. onPlaybackStart from controllers/playback/video.

The latter is difficult to reproduce. SyncPlay just probably triggers an additional event after sync.

If so, I think that's fine.

PeachesMLG commented 3 months ago

Yeah, your right, I didnt realise they were handlers listening to an event, I thought they were indicating an event was called/triggered.

soultaco83 commented 3 months ago

Good to know. For now I will revert the change back to the original and await a new update

Mondrethos commented 3 months ago

Went crazy trying to troubleshoot this over the last 2 days. Glad someone already make an issue.

thornbill commented 3 months ago

~@PeachesMLG Do you plan to open a PR?~

I opened a PR to try to get the fix in the next release.

soultaco83 commented 3 months ago

I have built the webui with the new change. This appears to be working. I will continue to test. Thank you for your work @PeachesMLG and @thornbill

chokonmainatsu commented 3 months ago

Is there a rough time window, when this will be released with version 10.9.2?

TimGels commented 3 months ago

Is there a rough time window, when this will be released with version 10.9.2?

As soon as it is ready. Don't expect it to take months.

PeachesMLG commented 3 months ago

~@PeachesMLG Do you plan to open a PR?~

I opened a PR to try to get the fix in the next release.

Sorry, I didnt want to raise one since I dont know the codebase well enough to know if there was any side effects to moving it

akhilesh171 commented 3 months ago

I am still experiencing this issue - can anyone confirm? Do I need to upload logs?

ellsclytn commented 2 months ago

@akhilesh171 yeah, still getting the same. Bumped Jellyfin to 10.9.6, and Jellyfin Media Player to 1.11.1.

Logs don't seem to reveal much, they just seem to mention that playback stopped, and that's about it:

[10:50:31] [INF] [8] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Media Player 1.11.1 playing Blue Sky Thinking. Stopped at 26560 ms
[10:50:31] [INF] [278] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Media Player 1.11.1 playing Blue Sky Thinking. Stopped at 26680 ms
[10:50:31] [INF] [8] Emby.Server.Implementations.SyncPlay.Group: Session ecdf24322f609487eb048d9a0c08d42c requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Playing.
[10:50:32] [INF] [22] Emby.Server.Implementations.SyncPlay.Group: Session fd9d8d84136c2c74af22c5fc1cac3f6d requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Playing.
[10:50:32] [INF] [14] Emby.Server.Implementations.SyncPlay.Group: Session 79e4971dce3643abcfaa9364f15e433e requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Playing.
[10:50:32] [INF] [22] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Media Player 1.11.1 playing Blue Sky Thinking. Stopped at 28119 ms
[10:50:32] [INF] [167] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Jellyfin Media Player 1.11.1 playing Blue Sky Thinking. Stopped at 26880 ms
[10:50:36] [INF] [209] Emby.Server.Implementations.SyncPlay.Group: Session fd9d8d84136c2c74af22c5fc1cac3f6d requested Play in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Playing.
[10:50:36] [INF] [209] Emby.Server.Implementations.SyncPlay.Group: Group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 switching from Playing to Waiting.
[10:50:36] [INF] [14] Emby.Server.Implementations.SyncPlay.Group: Session 3a7c5932b7ea55718b6115473ce20e48 requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [209] Emby.Server.Implementations.SyncPlay.Group: Session fd9d8d84136c2c74af22c5fc1cac3f6d requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [22] Emby.Server.Implementations.SyncPlay.Group: Session ecdf24322f609487eb048d9a0c08d42c requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [14] Emby.Server.Implementations.SyncPlay.Group: Session 79e4971dce3643abcfaa9364f15e433e requested IgnoreWait in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [323] Jellyfin.Api.Helpers.MediaInfoHelper: User policy for admin. EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[10:50:36] [INF] [323] Jellyfin.Api.Helpers.MediaInfoHelper: RemoteClientBitrateLimit: 1000000000, RemoteIP: <REDACTED>, IsInLocalNetwork: False
[10:50:36] [INF] [18] Jellyfin.Api.Helpers.MediaInfoHelper: User policy for jroqezusoljxe. EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[10:50:36] [INF] [18] Jellyfin.Api.Helpers.MediaInfoHelper: RemoteClientBitrateLimit: 1000000000, RemoteIP: <REDACTED>, IsInLocalNetwork: False
[10:50:36] [INF] [18] Jellyfin.Api.Helpers.MediaInfoHelper: User policy for pdppyiuscwuuj. EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[10:50:36] [INF] [18] Jellyfin.Api.Helpers.MediaInfoHelper: RemoteClientBitrateLimit: 1000000000, RemoteIP: <REDACTED>, IsInLocalNetwork: False
[10:50:36] [INF] [323] Jellyfin.Api.Helpers.MediaInfoHelper: User policy for egmqcobthosrm. EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[10:50:36] [INF] [323] Jellyfin.Api.Helpers.MediaInfoHelper: RemoteClientBitrateLimit: 1000000000, RemoteIP: <REDACTED>, IsInLocalNetwork: False
[10:50:36] [INF] [8] Emby.Server.Implementations.SyncPlay.Group: Session 3a7c5932b7ea55718b6115473ce20e48 requested Ready in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [8] MediaBrowser.Controller.SyncPlay.GroupStates.WaitingGroupState: Session 3a7c5932b7ea55718b6115473ce20e48 will pause when ready in -0.0030939 seconds. Group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 is waiting for all ready events.
[10:50:36] [INF] [326] Emby.Server.Implementations.SyncPlay.Group: Session fd9d8d84136c2c74af22c5fc1cac3f6d requested Ready in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:36] [INF] [326] MediaBrowser.Controller.SyncPlay.GroupStates.WaitingGroupState: Session fd9d8d84136c2c74af22c5fc1cac3f6d will pause when ready in -0.0028022 seconds. Group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 is waiting for all ready events.
[10:50:37] [INF] [22] Emby.Server.Implementations.SyncPlay.Group: Session ecdf24322f609487eb048d9a0c08d42c requested Ready in group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 that is Waiting.
[10:50:37] [INF] [22] MediaBrowser.Controller.SyncPlay.GroupStates.WaitingGroupState: Session ecdf24322f609487eb048d9a0c08d42c will pause when ready in -0.0036809 seconds. Group ee7268c8-9796-4fc1-adec-a8a60b8b1a44 is waiting for all ready events.
dmitrylyzo commented 2 months ago

Logs don't seem to reveal much, they just seem to mention that playback stopped, and that's about it

Because if it is caused by the client, you need to look at its logs.

Is there any error in the browser console? Or logs of JMP?

ellsclytn commented 2 months ago

Browser didn't experience the issue for anyone :thinking:.

I'll have a look into JMP console soon, just got to work out how to get the console/logs up for it.

ellsclytn commented 2 months ago

Client logs (21:49:13 being the moment of playback crash)

2024-06-12 21:48:45.355 [debug] unknown @ 0 - Disabling OS screensaver
2024-06-12 21:48:45.355 [critical] unknown @ 0 - doDisableScreensaver : failed to retrieve interface.
2024-06-12 21:48:45.858 [info] unknown @ 0 - JS: Sending web socket message: KeepAlive
2024-06-12 21:48:45.858 [info] unknown @ 0 - JS: Received KeepAlive from server.
2024-06-12 21:48:54.051 [info] unknown @ 0 - JS: Requesting url without automatic networking: https://jellyfin.domain/Sessions/Playing/Progress
2024-06-12 21:49:04.051 [info] unknown @ 0 - JS: Requesting url without automatic networking: https://jellyfin.domain/Sessions/Playing/Progress
2024-06-12 21:49:13.507 [info] unknown @ 0 - JS: Error while waiting for `playbackstart` event! startPlayback Timed out.
2024-06-12 21:49:13.507 [info] unknown @ 0 - JS: Requesting url without automatic networking: https://jellyfin.domain/SyncPlay/SetIgnoreWait
2024-06-12 21:49:13.509 [debug] unknown @ 0 - Enabling OS screensaver
2024-06-12 21:49:13.509 [info] unknown @ 0 - doEnableScreensaver : already enabled.
2024-06-12 21:49:13.509 [debug] unknown @ 0 - cplayer: EOF code: 4  
2024-06-12 21:49:13.510 [info] unknown @ 0 - JS: [nowPlayingBar:onPlaybackStopped] event: playbackstop
2024-06-12 21:49:13.510 [info] unknown @ 0 - JS: nowplaying event: playbackstop
2024-06-12 21:49:13.521 [debug] unknown @ 0 - cplayer: Set property: video-unscaled=false -> 1
2024-06-12 21:49:13.521 [debug] unknown @ 0 - cplayer: Set property: video-aspect-override="-1" -> 1
2024-06-12 21:49:13.521 [debug] unknown @ 0 - cplayer: Set property: keepaspect=true -> 1
2024-06-12 21:49:13.521 [debug] unknown @ 0 - cplayer: Set property: panscan=0.000000 -> 1
2024-06-12 21:49:13.521 [info] unknown @ 0 - Entering state: buffering
2024-06-12 21:49:13.522 [debug] unknown @ 0 - Enabling OS screensaver
2024-06-12 21:49:13.522 [info] unknown @ 0 - doEnableScreensaver : already enabled.
2024-06-12 21:49:13.522 [debug] unknown @ 0 - cplayer: Set property: speed=1.000000 -> 1
2024-06-12 21:49:13.522 [debug] unknown @ 0 - cplayer: Set property: sub-delay=0.000000 -> 1
2024-06-12 21:49:13.522 [debug] unknown @ 0 - Enabling OS screensaver
2024-06-12 21:49:13.522 [info] unknown @ 0 - doEnableScreensaver : already enabled.
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal playing to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal positionUpdate to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal finished to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal updateDuration to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal error to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Cannot find connection of signal paused to 
2024-06-12 21:49:13.522 [info] unknown @ 0 - JS: Requesting url without automatic networking: https://jellyfin.domain/Sessions/Playing/Stopped
2024-06-12 21:49:13.523 [info] unknown @ 0 - JS: [viewContainer] tryRestoreView [object Object]
2024-06-12 21:49:13.526 [debug] unknown @ 0 - cplayer: finished playback, success (reason 2)
2024-06-12 21:49:13.526 [info] unknown @ 0 - Entering state: canceled
2024-06-12 21:49:13.532 [info] unknown @ 0 - "DisplayManager found 1 Display(s)."
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Available modes for Display #0 (DisplayPort-0)"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  0:  3440 x 1440 x  0bpp @143.923Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  1:  3440 x 1440 x  0bpp @60.0006Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  2:  3440 x 1440 x  0bpp @99.9904Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  3:  1920 x 1200 x  0bpp @143.923Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  4:  1920 x 1080 x  0bpp @74.9769Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  5:  1920 x 1080 x  0bpp @60Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  6:  1920 x 1080 x  0bpp @60Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  7:  1920 x 1080 x  0bpp @50Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  8:  1920 x 1080 x  0bpp @59.9402Hz"
2024-06-12 21:49:13.532 [info] unknown @ 0 - "Mode  9:  1600 x 1200 x  0bpp @143.923Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 10:  1680 x 1050 x  0bpp @59.9543Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 11:  1600 x  900 x  0bpp @60Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 12:  1280 x 1024 x  0bpp @75.0247Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 13:  1280 x 1024 x  0bpp @60.0197Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 14:  1440 x  900 x  0bpp @143.923Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 15:  1280 x  800 x  0bpp @59.8103Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 16:  1152 x  864 x  0bpp @59.9718Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 17:  1280 x  720 x  0bpp @60Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 18:  1280 x  720 x  0bpp @50Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 19:  1280 x  720 x  0bpp @59.9402Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 20:  1024 x  768 x  0bpp @60.0038Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 21:   800 x  600 x  0bpp @60.3165Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 22:   720 x  576 x  0bpp @50Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 23:   720 x  480 x  0bpp @60Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 24:   720 x  480 x  0bpp @59.9401Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 25:   640 x  480 x  0bpp @60Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "Mode 26:   640 x  480 x  0bpp @59.9405Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - "DisplayManager : Current Display Mode on Display #0 is  3440 x 1440 x  0bpp @143.923Hz"
2024-06-12 21:49:13.533 [info] unknown @ 0 - Looking for a display at: QRect(1721,26 1718x1413) (center: QPoint(2579,732) )
2024-06-12 21:49:13.533 [info] unknown @ 0 - Display index: 0
2024-06-12 21:49:13.533 [info] unknown @ 0 - Looking for a display at: QRect(1721,26 1718x1413) (center: QPoint(2579,732) )
2024-06-12 21:49:13.533 [info] unknown @ 0 - Display index: 0
2024-06-12 21:49:13.533 [debug] unknown @ 0 - "Parsing other configuration: "
2024-06-12 21:49:13.533 [debug] unknown @ 0 - "Parsing other configuration: "
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: video-sync="audio" -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: hwdec="auto-copy" -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: hwdec-image-format="no" -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: deinterlace="no" -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: display-fps-override=143.922760 -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: audio-delay=0.000000 -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: demuxer-max-bytes=78643200 -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: video-unscaled=false -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: video-aspect-override="-1" -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: keepaspect=true -> 1
2024-06-12 21:49:13.534 [debug] unknown @ 0 - cplayer: Set property: panscan=0.000000 -> 1
2024-06-12 21:49:15.844 [info] unknown @ 0 - JS: Sending web socket message: KeepAlive
2024-06-12 21:49:15.845 [info] unknown @ 0 - JS: Received KeepAlive from server.
2024-06-12 21:49:28.157 [info] unknown @ 0 - JS: Requesting https://jellyfin.domain/GetUTCTime
dmitrylyzo commented 2 months ago

Hmm, the same error:

 [info] unknown @ 0 - JS: Error while waiting for `playbackstart` event! startPlayback Timed out.

Does JMP use webui from the server? AFAIK, JMP should now use the server webui by default. But maybe you need to force this manually if it is not a fresh install.

ellsclytn commented 2 months ago

Oh, good idea. I just tried that by clearing all config & cache for JMP, seems to have done the trick!

On Linux, I ran the following on both clients:

rm -rf ~/.config/jellyfin.org ~/.local/share/Jellyfin\ Media\ Player ~/.local/share/jellyfinmediaplayer ~/.cache/Jellyfin\ Media\ Player

Booted up JMP, logged in again, and seems to be all good. Thanks!