jellyfin / jellyfin-androidtv

Android TV Client for Jellyfin
https://jellyfin.org
GNU General Public License v2.0
2.72k stars 466 forks source link

0.12.3 - Video Files "Rewind" Themselves or Start Over Randomly #1239

Closed ShakeSp33r closed 1 year ago

ShakeSp33r commented 2 years ago

Describe the bug

Replay jump back to previous pause or resume from time.

Start Video from Beginning:

  1. Paused the video for about 3 min @ 0:58, and start playing again.
  2. Did not watch long before it "jumped back" to the time where I paused it (took about 1min before it jumped back)

Start Video from resume button:

  1. Stopping a video 5:23.
  2. Click on Resume from button on Video description screen and start watching again.
  3. Pause the video for 3 min & unpause the video again.
  4. Minute later the video jumped back to 5:23...

It appears to be when ever a media file is transcoded that this happen. I've tested a direct stream and the random rewind does not happen.

Application version

0.12.3

Device information

Skyworth TV Xiaomi Mi TV Stick Xiaomi Mi Box s 4k

Android version

Android 9

Jellyfin server version

10.7.7

lokiberra commented 2 years ago

This also happens to me. It will just skip back during playback. I am using 12.2 on a 2019 Nvidia Shield (tube version). Once it upgrades to 12.3 I will test again.

TheSpicyGentleman commented 2 years ago

I'm also having the exact same issues on my FireTV devices, and as noted above, only with transcoded files. I am not currently using any hardware transcoding.

App Version: 0.12.2 (on all devices)

Devices: Fire TV Cube Fire TV 4k Stick Fire TV 4k Stick Max

Android Version: Fire OS 7.2.5.5 (Fire TV 4k Stick Max) Fire OS 7.2.4.2 (Fire TV Cube) Fire OS 6.2.8.1 (Fire TV 4k Stick)

Jellyfin Server: 10.7.7 (linuxserver.io docker version)

mueslimak3r commented 2 years ago

Darn, this is similar or a duplicate of #400 , which I hoped to have fixed with pull request #1219 . I will look into this.

Please check in the dashboard for me: Start playback and click on the "i" button for that session in the dashboard and see what it says for the container. Does it say mkv?

mueslimak3r commented 2 years ago

@lokiberra in the context of skipping back/forward and seeking this issue should be fixed in 0.12.3. If after updating to 0.12.3 you still experience it please let me know

lokiberra commented 2 years ago

I'll give it a go tonight and let you know. It has updated to 12.3 so fingers crossed

mueslimak3r commented 2 years ago

@ShakeSp33r Also, can you try going to settings->preferred media player and changing that to "exoplayer", and see if that changes anything?

ShakeSp33r commented 2 years ago

@mueslimak3r

1) I am using 0.12.3 2) File Transcoding info as per Dashboard on Jellyfin Server : 6.5 Mbps MKV H264 AC3

Testing with preferred media player set to "exoplayer" As previously I testing playing media from beginning & resume played media. Both jump back after pausing for 3min. Media played from beginning, jumped back to start (00:00) & media played from resume jumped back to resume start point (10:52)

Testing with preferred media player set to "libVLC" Tested the same media file from start & resume. Both continued playing after pause. I did not have any jumping back to start or resume point, although the audio was a bid jittery.

Phoenix-004 commented 2 years ago

Had his problem on 0.12.2 and now 0.12.3.

Can any of you having the problem check to see if you have "downmix to stereo" selected in the audio settings?

I have noticed that whenever I have the app set to downmix to stereo, this problem pops up. How you know it's bugged out is that the Video time stamp just no longer updates. And then the video will then randomly just jump back to the beginning.

I can reproduce this error every single time, just by simply toggling on or off "downmix to stereo".

I believe this happens whenever any form of AUDIO transcoding or conversion is happening.

mueslimak3r commented 2 years ago

I'm having some trouble reproducing this issue but I am looking for the cause.

Any additional information you can provide like server logs, preferred player settings, etc could help me reproduce the issue on my end. Please make sure you remove any identifying information from the logs (ip address, domain name)

Downmix to stereo relating to this does give more weight to the possibility that this is due to transcoding playback being handled improperly.

lokiberra commented 2 years ago

The files I tested in 12.3 did not jump back last night. I was using exoplayer. The file that was jumping back previously was being transcoded due to a unsupported subtitle codec. If I notice it again I will check if it is being transcoded

Phoenix-004 commented 2 years ago

OK. I will try and give some more info.

In my case, I have my HTPC, connected to my Android TV. So basically, I switch from my HDMI input for the PC to the jellyfin app on the TV or any other TV in my house. All android TVs. Android OS ver 9. Jellyfin server 10.7.6

I have been using downmix to stereo for a while and this doesn't happen to every media file.But the latest culprit is the one I have attached a partial log for.

  1. If using downmix to stereo, the video time stamp will randomly seize to update and remain either at 0.00 if I just started a new video, or whatever time stamp I resumed from.
  2. switching back to direct removes the issue.

My gf uses my server remotely, also on android TVs, and I know she is not tech savvy enough to even have downmix to stereo selected. (hell, I set it up for her and I know I didn't set that up), she also randomly has this issue which also leads me to believe that this is something to do with any kinda audio/subtitle transcoding.

[2021-11-07 07:36:29.044 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-07 07:36:29.044 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:36:29.044 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:36:29.053 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:36:29.053 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:36:29.061 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:36:29.061 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:36:29.118 -04:00] [INF] /usr/bin/ffmpeg -ss 00:13:30.000 -i file:"/home/david/Videos/SHOWS/Arcane/Season 01/Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" -map 0:0 -map 0:1 -map -0:s -codec:v:0 libx264 -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,min(1920\,1080*dar))/2)*2:trunc(min(max(iw/dar\,ih)\,min(1920/dar\,1080))/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset superfast -crf 23 -maxrate 3222557 -bufsize 6445114 -profile:v:0 high -level 41 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 2 -ab 384000 -af "volume=2" -y "/var/lib/jellyfin/transcodes/93712cd33a3f3c2c00d09916009a0121.mkv" [2021-11-07 07:36:30.056 -04:00] [INF] Transcoding kill timer stopped for JobId "f19db1fb52514411accdc1e31be0e2ef" PlaySessionId "8e02b284b33546f8a0725e1ee345e809". Killing transcoding [2021-11-07 07:36:30.056 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/55207c9b4c32ed751c64c35bd194f4ff.mkv" [2021-11-07 07:36:30.540 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/videos/e7b46f04-ff8c-4232-17b2-31662b8a5bc4/stream.mkv?DeviceId=f30bd75c23d598f5d113cc11961b3daf224e30b1&MediaSourceId=e7b46f04ff8c423217b231662b8a5bc4&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&VideoBitrate=99616000&AudioBitrate=384000&StartTimeTicks=8100000000&PlaySessionId=466358ff688641a2975dca924f66208f&api_key=20728e80379e4d37b1210a91a070dae7&SubtitleMethod=Encode&CopyTimestamps=true&RequireAvc=false&Tag=9d222da10c2cfbb2eab6ba0e40b1b103&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&h264-maxrefframes=4&aac-audiochannels=2&mp3-audiochannels=2&TranscodeReasons=AudioCodecNotSupported&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.0.2" in 0:00:01.4283264 with Status Code 200 [2021-11-07 07:36:31.781 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:36:44.570 -04:00] [INF] Stopping ffmpeg process with q command for "/var/lib/jellyfin/transcodes/93712cd33a3f3c2c00d09916009a0121.mkv" [2021-11-07 07:36:44.765 -04:00] [INF] FFmpeg exited with code 0 [2021-11-07 07:36:44.765 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/93712cd33a3f3c2c00d09916009a0121.mkv" [2021-11-07 07:36:46.270 -04:00] [INF] Playback stopped reported by app "Android TV" "0.12.3" playing "TBA". Stopped at "814029" ms [2021-11-07 07:36:46.289 -04:00] [INF] Playback stop tracker found, processing stop : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:36:46.289 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/Sessions/Playing/Stopped" to "192.168.0.2" in 0:00:01.7202979 with Status Code 204 [2021-11-07 07:36:46.290 -04:00] [INF] PlaybackTracker : Adding Stop Event : 11/07/2021 07:36:46 [2021-11-07 07:36:46.290 -04:00] [INF] Saving playback tracking activity in DB [2021-11-07 07:36:46.779 -04:00] [INF] Starting User Changes Sync... [2021-11-07 07:36:46.858 -04:00] [INF] "USERSYNC" User "bc24de54664546fcb3b47894bdadd5b6"("David") posted 2 Updates: "e7b46f04ff8c423217b231662b8a5bc4,3142f6f1241a267f1b818184e1062b5f" [2021-11-07 07:36:46.858 -04:00] [INF] User Changes Sync Finished Taking "00:00:00.0788655"

mueslimak3r commented 2 years ago

@Phoenix-004 if that's all there is for that playback session, and that covers when you paused and resumed, it could be telling that the logs only show playback starting and then stopping, and ffmpeg exiting. I don't see anything about playback resuming.

I assume your issue is also triggered by pausing and resuming, or does it just happen on its own without any input? Did this start happening in 0.12.3 or has it been happening for a while, and if so do you remember when it started?

Phoenix-004 commented 2 years ago

@Phoenix-004 if that's all there is for that playback session, and that covers when you paused and resumed, it could be telling that the logs only show playback starting and then stopping, and ffmpeg exiting. I don't see anything about playback resuming.

I assume your issue is also triggered by pausing and resuming, or does it just happen on its own without any input? Did this start happening in 0.12.3 or has it been happening for a while, and if so do you remember when it started?

Started in 0.12.2. Continued in 0.12.3.

I just tried it again with what I sent you. BUt whats funny,is that that was actually a fileI was previously playing.But it just started from the beginning anyways.

Yes,its also triggered "sometimes" by pausing and resuming. Ad sometimes, it doesn't even happen at all. I just played that same file now, even with using "downmix to stereo" and it's working normally. I could start another file and the issue will pop up again, but once I remove "downmix to stereo" and set it to "direct" it stops.

The first time I noticed it was like two weeks ago. But that is only because up until two weeks ago, I had never used the downmix to stereo option. I was able to isolate the issue because when I noticed that the ONLY change I made to m set-up was toggling the audio output.

here is my most recent session log on the same file...still using downmix to stereo...but this time, everything is working. including the timestamp tracker. And I have changed nothing at all.

[2021-11-07 07:59:17.853 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-07 07:59:17.853 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:59:17.853 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:59:17.861 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:59:17.861 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:59:17.869 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-07 07:59:17.869 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Arcane\Season 01\Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" with codec "h264" [2021-11-07 07:59:18.072 -04:00] [INF] /usr/bin/ffmpeg -ss 00:13:34.029 -i file:"/home/david/Videos/SHOWS/Arcane/Season 01/Arcane - S01E01 - Welcome to the Playground WEBDL-1080p.mkv" -map 0:0 -map 0:1 -map -0:s -codec:v:0 libx264 -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,min(1920\,1080*dar))/2)*2:trunc(min(max(iw/dar\,ih)\,min(1920/dar\,1080))/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset superfast -crf 23 -maxrate 3222557 -bufsize 6445114 -profile:v:0 high -level 41 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 2 -ab 384000 -af "volume=2" -y "/var/lib/jellyfin/transcodes/0d5c9b28735c81c051119ae03122535e.mkv" [2021-11-07 07:59:18.495 -04:00] [INF] Adding playback tracker : f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4 [2021-11-07 07:59:18.517 -04:00] [INF] PlaybackTracker : Adding Start Event : 11/07/2021 07:59:18 [2021-11-07 07:59:18.517 -04:00] [INF] Creating StartPlaybackTimer Task [2021-11-07 07:59:18.517 -04:00] [INF] StartPlaybackTimer : Entered [2021-11-07 07:59:18.903 -04:00] [INF] Starting User Changes Sync... [2021-11-07 07:59:19.010 -04:00] [INF] "USERSYNC" User "bc24de54664546fcb3b47894bdadd5b6"("David") posted 2 Updates: "e7b46f04ff8c423217b231662b8a5bc4,3142f6f1241a267f1b818184e1062b5f" [2021-11-07 07:59:19.010 -04:00] [INF] User Changes Sync Finished Taking "00:00:00.1070342" [2021-11-07 07:59:19.231 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:24.282 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/videos/e7b46f04-ff8c-4232-17b2-31662b8a5bc4/stream.mkv?DeviceId=f30bd75c23d598f5d113cc11961b3daf224e30b1&MediaSourceId=e7b46f04ff8c423217b231662b8a5bc4&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&VideoBitrate=99616000&AudioBitrate=384000&StartTimeTicks=8140290000&PlaySessionId=348767a046254e26a2d32a1a6cdcd322&api_key=20728e80379e4d37b1210a91a070dae7&CopyTimestamps=true&RequireAvc=false&Tag=9d222da10c2cfbb2eab6ba0e40b1b103&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&h264-maxrefframes=4&aac-audiochannels=2&mp3-audiochannels=2&TranscodeReasons=AudioCodecNotSupported&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.0.2" in 0:00:06.2133676 with Status Code 200 [2021-11-07 07:59:38.348 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 07:59:38.516 -04:00] [INF] session.RemoteEndPoint : "192.168.0.2" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : event_playing_id = "e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : event_user_id = "bc24de54664546fcb3b47894bdadd5b6" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : event_user_id_int = 1 [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : session_playing_id = "e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : session_user_id = "bc24de54664546fcb3b47894bdadd5b6" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : play_method = "Transcode (v:h264 a:aac)" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : e.ClientName = "Android TV" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : e.DeviceName = "Davids TV" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : ItemName = "Arcane - s01e01 - TBA" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : ItemId = "e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : ItemType = "Episode" [2021-11-07 07:59:38.516 -04:00] [INF] StartPlaybackTimer : All matches, playback registered [2021-11-07 07:59:38.516 -04:00] [INF] Playback tracker found, adding playback info : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:38.516 -04:00] [INF] Saving playback tracking activity in DB [2021-11-07 07:59:38.610 -04:00] [INF] StartPlaybackTimer : Exited [2021-11-07 07:59:39.458 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 07:59:50.346 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 07:59:59.489 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:00:19.510 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:00:38.351 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:00:40.486 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:00:50.358 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:01:01.323 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:01:21.548 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:01:38.359 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:01:42.507 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:01:50.363 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:02:02.550 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:02:22.569 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:02:38.374 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:02:42.582 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:02:50.374 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:03:02.599 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:03:23.586 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:03:38.380 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:03:43.593 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:03:50.378 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:04:03.615 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:04:24.610 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:04:38.380 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:04:44.612 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:04:50.383 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:05:04.637 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:05:24.707 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:05:38.387 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:05:44.723 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:05:50.386 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:06:04.816 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:06:25.724 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:06:38.390 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:06:45.732 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:06:50.394 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:07:05.734 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:07:25.742 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:07:38.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:07:45.747 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:07:50.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:08:05.791 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:08:25.845 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:08:38.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:08:45.870 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:08:50.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:09:05.889 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:09:25.892 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:09:38.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:09:45.896 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:09:50.405 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:10:05.899 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:10:25.903 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:10:38.404 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:10:46.902 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:10:50.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:11:06.914 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:11:23.306 -04:00] [INF] FFmpeg exited with code 0 [2021-11-07 08:11:26.959 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:11:38.404 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:11:46.967 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:11:50.403 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:12:07.415 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:12:27.975 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:12:38.403 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:12:48.952 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:12:50.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:13:08.992 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:13:29.004 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:13:38.402 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:13:49.998 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:13:50.404 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:14:10.003 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:14:30.052 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:14:38.408 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:14:50.063 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:14:50.408 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:15:10.069 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:15:12.339 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:12.340 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:15:12.340 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:14.351 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:14.351 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:15:14.351 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:16.378 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:16.378 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:15:16.378 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:18.395 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:18.396 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:15:18.396 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:15:30.080 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:15:38.407 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:15:50.081 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:15:50.408 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:16:10.087 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:16:30.096 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:16:38.408 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:16:50.097 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:16:50.407 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:17:10.109 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:17:30.128 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:17:38.407 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:17:50.130 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:17:50.407 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:18:10.139 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:18:30.144 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:18:38.406 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:18:50.151 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:18:50.408 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:19:10.160 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:19:30.160 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:19:38.407 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:19:50.163 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:19:50.406 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:20:10.186 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:20:30.231 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:20:32.073 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:32.073 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:20:32.073 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:34.085 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:34.086 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:20:34.086 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:36.103 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:36.103 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:20:36.103 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:38.120 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:38.120 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-07 08:20:38.120 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-07 08:20:38.410 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:20:50.287 -04:00] [INF] Processing playback tracker : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:20:50.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:21:08.673 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/0d5c9b28735c81c051119ae03122535e.mkv" [2021-11-07 08:21:10.259 -04:00] [INF] Playback stopped reported by app "Android TV" "0.12.3" playing "TBA". Stopped at "2110426" ms [2021-11-07 08:21:10.294 -04:00] [INF] Playback stop tracker found, processing stop : "f30bd75c23d598f5d113cc11961b3daf224e30b1-bc24de54664546fcb3b47894bdadd5b6-e7b46f04ff8c423217b231662b8a5bc4" [2021-11-07 08:21:10.294 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/Sessions/Playing/Stopped" to "192.168.0.2" in 0:00:01.6232549 with Status Code 204 [2021-11-07 08:21:10.295 -04:00] [INF] PlaybackTracker : Adding Stop Event : 11/07/2021 08:21:10 [2021-11-07 08:21:10.296 -04:00] [INF] Saving playback tracking activity in DB [2021-11-07 08:21:10.768 -04:00] [INF] Starting User Changes Sync... [2021-11-07 08:21:10.930 -04:00] [INF] "USERSYNC" User "bc24de54664546fcb3b47894bdadd5b6"("David") posted 2 Updates: "e7b46f04ff8c423217b231662b8a5bc4,3142f6f1241a267f1b818184e1062b5f" [2021-11-07 08:21:10.930 -04:00] [INF] User Changes Sync Finished Taking "00:00:00.1610624" [2021-11-07 08:21:38.411 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:21:50.411 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:22:38.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:22:50.410 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:23:38.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:23:50.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:24:38.411 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:24:50.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:25:38.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:25:50.412 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:26:38.415 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:26:50.417 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:27:38.415 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:27:50.415 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:28:38.415 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:28:50.420 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:29:38.421 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:29:50.419 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:30:38.420 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets. [2021-11-07 08:30:50.419 -04:00] [INF] Sending ForceKeepAlive message to 1 inactive WebSockets.

TheSpicyGentleman commented 2 years ago

All my Fire TV devices have updated to 12.3 and the issue still happening for me.

The container is an mkv, it's set to exoplayer, and the audio is set to direct stream.

I'll be happy to provide any logs I can to assist.

mueslimak3r commented 2 years ago

If any of you have the means to build the jellyfin android-tv client from source, I'm testing out some stuff and it would be useful to see if it fixes this issue.

Here is the branch to clone: https://github.com/mueslimak3r/jellyfin-androidtv/tree/misc-playback-adjustments

Phoenix-004 commented 2 years ago

@mueslimak3r sorry I can't build... running Linux. :(

If you have a pre-built apk you can share I will be willing to side-load and test it though.

TheSpicyGentleman commented 2 years ago

@mueslimak3r Same as @Phoenix-004 I don't have the means, but would be more than happy to test an apk and side-load.

nielsvanvelzen commented 2 years ago

https://github.com/jellyfin/jellyfin-androidtv/suites/4311024594/artifacts/112636838 (taken from the pull request #1248)

TheSpicyGentleman commented 2 years ago

Brilliant. I'll test in a few hours when I'm off work and report back.

Thanks.

Phoenix-004 commented 2 years ago

ok. gonna test it now... will give feedback tomorrow.

TheSpicyGentleman commented 2 years ago

The first mkv I tried the same issue appear. I paused for a few second, played, and the skip-back occurred 15-20 min later. I tested using the above provided apk sideloaded on Fire TV Stick 4k, using exoplayer, and direct audio.

It appears that "automatically select" was using LibVLC, and the audio was out of sync but seemed to work fine in the sense of skip-back as it wasn't transcoding.

Happy to provide any logs or further testing.y

Phoenix-004 commented 2 years ago

Still happens. And yes, only with content an mkv container. Tested using the provided Jellyfin debug.apk

If playing an mp4, and you skip forward, the seek bar scrubs through the file as expected, and when you stop to play, it stays right there. This is normal and expected behavior.

When playing an mkv however, and you do the same thing, the seek bar scrubs through, but when you stop to play, for a brief second, it jumps back to the beginning of the file, then jumps to where you stopped for playback. And plays, but then after a while, and the timing is random, it will either jump back to where you resumed from or jump back to the beginning of the video if you started the video and just skipped forward to a point in the video.

I am using the downmix to stereo setting, and this doesn't happen with using direct audio at all on my system or at home. But outside my home, remote streaming, even using direct audio this still happens, as in that case, the video is probably being transcoded to fit into a smaller bitrate for steaming as I had set it.

ShakeSp33r commented 2 years ago

Okay, I tested with the above side loaded...

Testing with preferred media player set to "exoplayer" and "Direct Audio" As previously I testing playing media from beginning & resume played media. Both jump back after pausing for 3min. Media played from beginning, jumped back to start (00:00) & media played from resume jumped back to resume start point (10:52)

Testing with preferred media player set to "exoplayer" and "Downmix to Stereo" Same result. System jump back after pausing.

Then I checked the connection to the server and on the above 2 tests I used the DNS entry that force the system through the reverse proxy & SSL encryption.

After reconnecting to the server through the internal IP:Port address (using the file above) I did the above test again, and the system did not jump back, and I could watch the entire media without and issue. So from what I've seen is if the server do transcoding "5.1 Mbps MKV H264 AAC" and going through the reverse proxy (using nginx) it jumps back.

@TheSpicyGentleman - Could you check if this is the case on your side too...?

TheSpicyGentleman commented 2 years ago

Sure thing @ShakeSp33r .

I am actually running exactly as you are, nginx reverse proxy w/ SSL.

I'll test shortly and report back.

TheSpicyGentleman commented 2 years ago

Ok, so I tested the same file twice. Once with the supplied debug apk and other with the stable 0.12.3. Both paused, resumed, and didn't skip-back when I bypassed my nginx reverse proxy.

I, like @ShakeSp33r, force (via DNS) all my connections through the reverse proxy.

It does now seem related to passing the transcode via reverse proxy.

Phoenix-004 commented 2 years ago

@TheSpicyGentleman I don't use any form of proxy. For my use case, I direct stream all my content on my home network, and even when streaming remotely, to the one person I share my stuff with, it's done directly through my home IP address.

One thing for certain is that whenever transcoding is being done, this issue tends to pop up. But it's weird.

On my home network, everything works fine as long as I leave the audio output set to direct. The second I choose downmix to stereo, this issue pops u, but so far... only with .mkv files.

When accessing the library remotely, it happens regardless of audio settings and file container. I suspect that is because I have my remote streaming bitrate limits set to under 4mbs (due to my ISP upload limitations) so most content will be transcoded to fit that bitrate.

TheSpicyGentleman commented 2 years ago

@Phoenix-004 Interesting. I'll continue to test with other mkv files and see if I can get it to repeat as well on my end both internally and externally.

I don't do a lot of external streaming, but I do have it configured, but only via proxy. I'll have to do some changes on my end to get it to direct play. But I'm happy to test. Downside is I don't have anyone or any way to easily test android tv externally as all of my external access/users are Android devices not Android TV so I don't think it would be an apples to apples test.

I can say for sure it has never happened on a direct play file. Only transcode. Only mkv. At least in my case. I'll try setting to downmix as well to see if I can get it to pop up in testing.

mueslimak3r commented 2 years ago

So with this test version you tried the audio is out of sync when it previously wasn't? As in, this test version broke things more?

mueslimak3r commented 2 years ago

Regarding the reverse proxy observations, it's possible that something in the reverse proxy configuration could be affecting things. However, it still seems more likely that it's just a transcoding issue.

If y'all could post logs from the debug version it has some extra printouts for events like pausing and showing timestamps, so that could be useful

TheSpicyGentleman commented 2 years ago

@mueslimak3r Sorry, let me clarify. I've always had out of sync issues with libvlc. With the latest debug version it was, by default, set to automatically select which normally selects exoplayer in my experience, but it seemed to choose libvlc this time, and the audio was out of sync. When using exoplayer I have zero audio sync issues.

I only mentioned it to be thorough, not to confuse, my bad.

TheSpicyGentleman commented 2 years ago

One other thing I noticed when going through proxy vs directly is that under the Dashboard and Active Devices, the playback only shows the Message icon under the active playback. I don't see the play/stop or "i" at all. If I play the same file directly those show up. I'm not sure if this is a configuration issues on my end, by design, or just something weird in general.

I'll see if I can pull those logs for you.

Phoenix-004 commented 2 years ago

Just happened again.

  1. mkv file
  2. downmix to stereo
  3. anytime i tried to seek, on stping seek barwil glitch back to 0.00 then jump back to whre I stopped seeking and resume playback from there. then when the bug hapens,it jumps backto that resume point.
  4. using jellyfin debug.apk

here is a log 0f my most recent session and right after it happened. [2021-11-12 00:55:15.792 -04:00] [INF] GetPostedPlaybackInfo profile: DeviceProfile { Name: "AndroidTV-libVLC", Id: null, Identification: null, FriendlyName: null, Manufacturer: null, ManufacturerUrl: null, ModelName: null, ModelDescription: null, ModelNumber: null, ModelUrl: null, SerialNumber: null, EnableAlbumArtInDidl: False, EnableSingleAlbumArtLimit: False, EnableSingleSubtitleLimit: False, SupportedMediaTypes: "Audio,Photo,Video", UserId: null, AlbumArtPn: null, MaxAlbumArtWidth: 0, MaxAlbumArtHeight: 0, MaxIconWidth: null, MaxIconHeight: null, MaxStreamingBitrate: 20000000, MaxStaticBitrate: 100000000, MusicStreamingTranscodingBitrate: 128000, MaxStaticMusicBitrate: null, SonyAggregationFlags: null, ProtocolInfo: null, TimelineOffsetSeconds: 0, RequiresPlainVideoItems: False, RequiresPlainFolders: False, EnableMSMediaReceiverRegistrar: False, IgnoreTranscodeByteRangeRequests: False, XmlRootAttributes: [], DirectPlayProfiles: [DirectPlayProfile { Container: "m4v,3gp,ts,mpegts,mov,xvid,vob,mkv,wmv,asf,ogm,ogv,m2v,avi,mpg,mpeg,mp4,webm,wtv", AudioCodec: "aac,mp3,mp2,ac3,wma,wmav2,dca,dts,pcm,PCM_S16LE,PCM_S24LE,opus,flac,truehd", VideoCodec: null, Type: Video }, DirectPlayProfile { Container: "flac,aac,mp3,mpa,wav,wma,mp2,ogg,oga,webma,ape", AudioCodec: null, VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "jpg,jpeg,png,gif,webp", AudioCodec: null, VideoCodec: null, Type: Photo }], TranscodingProfiles: [TranscodingProfile { Container: "mkv", Type: Video, VideoCodec: "h264", AudioCodec: "aac,mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: True, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }, TranscodingProfile { Container: "mp3", Type: Audio, VideoCodec: null, AudioCodec: "mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: False, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }], ContainerProfiles: [ContainerProfile { Type: Video, Conditions: [ProfileCondition { Condition: NotEquals, Property: VideoCodecTag, Value: "xvid", IsRequired: False }], Container: "avi" }], CodecProfiles: [CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: NotEquals, Property: VideoProfile, Value: "none", IsRequired: False }], ApplyConditions: [], Codec: "hevc", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: EqualsAny, Property: VideoProfile, Value: "high|main|baseline|constrained baseline", IsRequired: False }, ProfileCondition { Condition: LessThanEqual, Property: VideoLevel, Value: "51", IsRequired: False }], ApplyConditions: [], Codec: "h264", Container: null }, CodecProfile { Type: VideoAudio, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: AudioChannels, Value: "8", IsRequired: False }], ApplyConditions: [], Codec: null, Container: null }], ResponseProfiles: [], SubtitleProfiles: [SubtitleProfile { Format: "srt", Method: External, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "srt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "subrip", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ass", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ssa", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgs", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgssub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "dvdsub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "vtt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "sub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "smi", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "idx", Method: Embed, DidlMode: null, Language: null, Container: null }] } [2021-11-12 00:55:15.812 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-12 00:55:15.812 -04:00] [INF] Profile: "AndroidTV-libVLC", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:15.813 -04:00] [INF] Profile: "AndroidTV-libVLC", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:15.823 -04:00] [INF] Profile: "AndroidTV-libVLC", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:15.823 -04:00] [INF] Profile: "AndroidTV-libVLC", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:15.833 -04:00] [INF] Profile: "AndroidTV-libVLC", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:15.833 -04:00] [INF] Profile: "AndroidTV-libVLC", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:15.988 -04:00] [INF] GetPostedPlaybackInfo profile: DeviceProfile { Name: "AndroidTV-ExoPlayer", Id: null, Identification: null, FriendlyName: null, Manufacturer: null, ManufacturerUrl: null, ModelName: null, ModelDescription: null, ModelNumber: null, ModelUrl: null, SerialNumber: null, EnableAlbumArtInDidl: False, EnableSingleAlbumArtLimit: False, EnableSingleSubtitleLimit: False, SupportedMediaTypes: "Audio,Photo,Video", UserId: null, AlbumArtPn: null, MaxAlbumArtWidth: 0, MaxAlbumArtHeight: 0, MaxIconWidth: null, MaxIconHeight: null, MaxStreamingBitrate: 20000000, MaxStaticBitrate: 100000000, MusicStreamingTranscodingBitrate: 128000, MaxStaticMusicBitrate: null, SonyAggregationFlags: null, ProtocolInfo: null, TimelineOffsetSeconds: 0, RequiresPlainVideoItems: False, RequiresPlainFolders: False, EnableMSMediaReceiverRegistrar: False, IgnoreTranscodeByteRangeRequests: False, XmlRootAttributes: [], DirectPlayProfiles: [DirectPlayProfile { Container: "m4v,mov,xvid,vob,mkv,wmv,asf,ogm,ogv,mp4,webm", AudioCodec: "aac,mp3,mp2", VideoCodec: "h264,hevc,vp8,vp9,mpeg,mpeg2video", Type: Video }, DirectPlayProfile { Container: "aac,mp3,mpa,flac,wav,wma,mp2,ogg,oga,webma,ape,opus", AudioCodec: null, VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "jpg,jpeg,png,gif,webp", AudioCodec: null, VideoCodec: null, Type: Photo }], TranscodingProfiles: [TranscodingProfile { Container: "mkv", Type: Video, VideoCodec: "h264", AudioCodec: "aac,mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: True, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }, TranscodingProfile { Container: "mp3", Type: Audio, VideoCodec: null, AudioCodec: "mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: False, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }], ContainerProfiles: [], CodecProfiles: [CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: EqualsAny, Property: VideoProfile, Value: "high|main|baseline|constrained baseline", IsRequired: False }, ProfileCondition { Condition: LessThanEqual, Property: VideoLevel, Value: "51", IsRequired: False }], ApplyConditions: [], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "12", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1200", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "4", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1900", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: NotEquals, Property: VideoProfile, Value: "none", IsRequired: False }], ApplyConditions: [], Codec: "hevc", Container: null }, CodecProfile { Type: VideoAudio, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: AudioChannels, Value: "6", IsRequired: False }], ApplyConditions: [], Codec: null, Container: null }], ResponseProfiles: [], SubtitleProfiles: [SubtitleProfile { Format: "srt", Method: External, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "srt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "subrip", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ass", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ssa", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgs", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgssub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "dvdsub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "vtt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "sub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "idx", Method: Embed, DidlMode: null, Language: null, Container: null }] } [2021-11-12 00:55:16.004 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-12 00:55:16.004 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:16.004 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:16.015 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:16.015 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:16.025 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:55:16.025 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:55:16.463 -04:00] [INF] /usr/bin/ffmpeg -i file:"/home/david/Videos/SHOWS/Invasion (2021)/Season 01/Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" -map 0:0 -map 0:1 -map 0:2 -codec:v:0 libx264 -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,min(1356\,678*dar))/2)*2:trunc(min(max(iw/dar\,ih)\,min(1356/dar\,678))/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset superfast -crf 23 -maxrate 3608508 -bufsize 7217016 -profile:v:0 high -level 41 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 2 -ab 384000 -af "volume=2" -codec:s:0 copy -disposition:s:0 default -y "/var/lib/jellyfin/transcodes/9dfcb9c6612e0ab522b00b7c5ce216bf.mkv" [2021-11-12 00:55:16.779 -04:00] [INF] Adding playback tracker : d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14 [2021-11-12 00:55:16.780 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/Sessions/Playing" to "192.168.0.2" in 0:00:00.5641846 with Status Code 204 [2021-11-12 00:55:16.808 -04:00] [INF] PlaybackTracker : Adding Start Event : 11/12/2021 00:55:16 [2021-11-12 00:55:16.808 -04:00] [INF] Creating StartPlaybackTimer Task [2021-11-12 00:55:16.808 -04:00] [INF] StartPlaybackTimer : Entered [2021-11-12 00:55:17.248 -04:00] [INF] Starting User Changes Sync... [2021-11-12 00:55:17.328 -04:00] [INF] "USERSYNC" User "bc24de54664546fcb3b47894bdadd5b6"("David") posted 2 Updates: "403b5fa9e7e5fc8d4c4345f344c7ea14,d622ae2a73c7d9774162d4f51f7fc2f9" [2021-11-12 00:55:17.328 -04:00] [INF] User Changes Sync Finished Taking "00:00:00.0794571" [2021-11-12 00:55:17.477 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:21.008 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/videos/403b5fa9-e7e5-fc8d-4c43-45f344c7ea14/stream.mkv?DeviceId=d04f3aea23877759080e05aeccac9da499f950e2&MediaSourceId=403b5fa9e7e5fc8d4c4345f344c7ea14&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&SubtitleStreamIndex=2&VideoBitrate=99616000&AudioBitrate=384000&PlaySessionId=d4a67cab7cd24efabbd737ba1eb3fb34&api_key=ce139a00b81144ec91c71fa92cdcf8ec&SubtitleMethod=Embed&CopyTimestamps=true&RequireAvc=false&Tag=c1fade5f5c186727d339ad268c85fe3d&SubtitleCodec=subrip&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&h264-maxrefframes=12&aac-audiochannels=2&mp3-audiochannels=2&TranscodeReasons=AudioCodecNotSupported&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.0.2" in 0:00:04.7828503 with Status Code 200 [2021-11-12 00:55:36.815 -04:00] [INF] session.RemoteEndPoint : "192.168.0.2" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : event_playing_id = "403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : event_user_id = "bc24de54664546fcb3b47894bdadd5b6" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : event_user_id_int = 1 [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : session_playing_id = "403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : session_user_id = "bc24de54664546fcb3b47894bdadd5b6" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : play_method = "Transcode (v:h264 a:aac)" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : e.ClientName = "Android TV" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : e.DeviceName = "Davids TV" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : ItemName = "Invasion - s01e06 - Home Invasion" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : ItemId = "403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : ItemType = "Episode" [2021-11-12 00:55:36.816 -04:00] [INF] StartPlaybackTimer : All matches, playback registered [2021-11-12 00:55:36.816 -04:00] [INF] Playback tracker found, adding playback info : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:36.816 -04:00] [INF] Saving playback tracking activity in DB [2021-11-12 00:55:36.847 -04:00] [INF] StartPlaybackTimer : Exited [2021-11-12 00:55:37.612 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:55:57.960 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:56:17.964 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:56:37.992 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:56:57.993 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:57:16.108 -04:00] [INF] Stopping ffmpeg process with q command for "/var/lib/jellyfin/transcodes/9dfcb9c6612e0ab522b00b7c5ce216bf.mkv" [2021-11-12 00:57:16.351 -04:00] [INF] FFmpeg exited with code 0 [2021-11-12 00:57:16.351 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/9dfcb9c6612e0ab522b00b7c5ce216bf.mkv" [2021-11-12 00:57:16.365 -04:00] [INF] GetPostedPlaybackInfo profile: DeviceProfile { Name: "AndroidTV-ExoPlayer", Id: null, Identification: null, FriendlyName: null, Manufacturer: null, ManufacturerUrl: null, ModelName: null, ModelDescription: null, ModelNumber: null, ModelUrl: null, SerialNumber: null, EnableAlbumArtInDidl: False, EnableSingleAlbumArtLimit: False, EnableSingleSubtitleLimit: False, SupportedMediaTypes: "Audio,Photo,Video", UserId: null, AlbumArtPn: null, MaxAlbumArtWidth: 0, MaxAlbumArtHeight: 0, MaxIconWidth: null, MaxIconHeight: null, MaxStreamingBitrate: 20000000, MaxStaticBitrate: 100000000, MusicStreamingTranscodingBitrate: 128000, MaxStaticMusicBitrate: null, SonyAggregationFlags: null, ProtocolInfo: null, TimelineOffsetSeconds: 0, RequiresPlainVideoItems: False, RequiresPlainFolders: False, EnableMSMediaReceiverRegistrar: False, IgnoreTranscodeByteRangeRequests: False, XmlRootAttributes: [], DirectPlayProfiles: [DirectPlayProfile { Container: "m4v,mov,xvid,vob,mkv,wmv,asf,ogm,ogv,mp4,webm", AudioCodec: "aac,mp3,mp2", VideoCodec: "h264,hevc,vp8,vp9,mpeg,mpeg2video", Type: Video }, DirectPlayProfile { Container: "aac,mp3,mpa,flac,wav,wma,mp2,ogg,oga,webma,ape,opus", AudioCodec: null, VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "jpg,jpeg,png,gif,webp", AudioCodec: null, VideoCodec: null, Type: Photo }], TranscodingProfiles: [TranscodingProfile { Container: "mkv", Type: Video, VideoCodec: "h264", AudioCodec: "aac,mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: True, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }, TranscodingProfile { Container: "mp3", Type: Audio, VideoCodec: null, AudioCodec: "mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: False, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }], ContainerProfiles: [], CodecProfiles: [CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: EqualsAny, Property: VideoProfile, Value: "high|main|baseline|constrained baseline", IsRequired: False }, ProfileCondition { Condition: LessThanEqual, Property: VideoLevel, Value: "51", IsRequired: False }], ApplyConditions: [], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "12", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1200", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "4", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1900", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: NotEquals, Property: VideoProfile, Value: "none", IsRequired: False }], ApplyConditions: [], Codec: "hevc", Container: null }, CodecProfile { Type: VideoAudio, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: AudioChannels, Value: "6", IsRequired: False }], ApplyConditions: [], Codec: null, Container: null }], ResponseProfiles: [], SubtitleProfiles: [SubtitleProfile { Format: "srt", Method: External, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "srt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "subrip", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ass", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ssa", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgs", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgssub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "dvdsub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "vtt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "sub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "idx", Method: Embed, DidlMode: null, Language: null, Container: null }] } [2021-11-12 00:57:16.384 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-12 00:57:16.384 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:16.384 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:16.394 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:16.394 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:16.403 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:16.403 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:16.506 -04:00] [INF] /usr/bin/ffmpeg -ss 00:02:30.000 -i file:"/home/david/Videos/SHOWS/Invasion (2021)/Season 01/Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" -map 0:0 -map 0:1 -map -0:s -codec:v:0 libx264 -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,min(1356\,678*dar))/2)*2:trunc(min(max(iw/dar\,ih)\,min(1356/dar\,678))/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset superfast -crf 23 -maxrate 3608508 -bufsize 7217016 -profile:v:0 high -level 41 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 2 -ab 384000 -af "volume=2" -y "/var/lib/jellyfin/transcodes/b10a49994a0abcc03912ad5e7680edaf.mkv" [2021-11-12 00:57:17.829 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/videos/403b5fa9-e7e5-fc8d-4c43-45f344c7ea14/stream.mkv?DeviceId=d04f3aea23877759080e05aeccac9da499f950e2&MediaSourceId=403b5fa9e7e5fc8d4c4345f344c7ea14&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&VideoBitrate=99616000&AudioBitrate=384000&StartTimeTicks=1500000000&PlaySessionId=89578e75b0ba47b9aaf8bcf9dd50ef72&api_key=ce139a00b81144ec91c71fa92cdcf8ec&SubtitleMethod=Encode&CopyTimestamps=true&RequireAvc=false&Tag=c1fade5f5c186727d339ad268c85fe3d&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&h264-maxrefframes=12&aac-audiochannels=2&mp3-audiochannels=2&TranscodeReasons=AudioCodecNotSupported&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.0.2" in 0:00:01.3565862 with Status Code 200 [2021-11-12 00:57:18.120 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:57:25.998 -04:00] [INF] Stopping ffmpeg process with q command for "/var/lib/jellyfin/transcodes/b10a49994a0abcc03912ad5e7680edaf.mkv" [2021-11-12 00:57:26.192 -04:00] [INF] FFmpeg exited with code 0 [2021-11-12 00:57:26.192 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/b10a49994a0abcc03912ad5e7680edaf.mkv" [2021-11-12 00:57:26.212 -04:00] [INF] GetPostedPlaybackInfo profile: DeviceProfile { Name: "AndroidTV-ExoPlayer", Id: null, Identification: null, FriendlyName: null, Manufacturer: null, ManufacturerUrl: null, ModelName: null, ModelDescription: null, ModelNumber: null, ModelUrl: null, SerialNumber: null, EnableAlbumArtInDidl: False, EnableSingleAlbumArtLimit: False, EnableSingleSubtitleLimit: False, SupportedMediaTypes: "Audio,Photo,Video", UserId: null, AlbumArtPn: null, MaxAlbumArtWidth: 0, MaxAlbumArtHeight: 0, MaxIconWidth: null, MaxIconHeight: null, MaxStreamingBitrate: 20000000, MaxStaticBitrate: 100000000, MusicStreamingTranscodingBitrate: 128000, MaxStaticMusicBitrate: null, SonyAggregationFlags: null, ProtocolInfo: null, TimelineOffsetSeconds: 0, RequiresPlainVideoItems: False, RequiresPlainFolders: False, EnableMSMediaReceiverRegistrar: False, IgnoreTranscodeByteRangeRequests: False, XmlRootAttributes: [], DirectPlayProfiles: [DirectPlayProfile { Container: "m4v,mov,xvid,vob,mkv,wmv,asf,ogm,ogv,mp4,webm", AudioCodec: "aac,mp3,mp2", VideoCodec: "h264,hevc,vp8,vp9,mpeg,mpeg2video", Type: Video }, DirectPlayProfile { Container: "aac,mp3,mpa,flac,wav,wma,mp2,ogg,oga,webma,ape,opus", AudioCodec: null, VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "jpg,jpeg,png,gif,webp", AudioCodec: null, VideoCodec: null, Type: Photo }], TranscodingProfiles: [TranscodingProfile { Container: "mkv", Type: Video, VideoCodec: "h264", AudioCodec: "aac,mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: True, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }, TranscodingProfile { Container: "mp3", Type: Audio, VideoCodec: null, AudioCodec: "mp3", Protocol: null, EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: False, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }], ContainerProfiles: [], CodecProfiles: [CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: EqualsAny, Property: VideoProfile, Value: "high|main|baseline|constrained baseline", IsRequired: False }, ProfileCondition { Condition: LessThanEqual, Property: VideoLevel, Value: "51", IsRequired: False }], ApplyConditions: [], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "12", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1200", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: RefFrames, Value: "4", IsRequired: False }], ApplyConditions: [ProfileCondition { Condition: GreaterThanEqual, Property: Width, Value: "1900", IsRequired: False }], Codec: "h264", Container: null }, CodecProfile { Type: Video, Conditions: [ProfileCondition { Condition: NotEquals, Property: VideoProfile, Value: "none", IsRequired: False }], ApplyConditions: [], Codec: "hevc", Container: null }, CodecProfile { Type: VideoAudio, Conditions: [ProfileCondition { Condition: LessThanEqual, Property: AudioChannels, Value: "6", IsRequired: False }], ApplyConditions: [], Codec: null, Container: null }], ResponseProfiles: [], SubtitleProfiles: [SubtitleProfile { Format: "srt", Method: External, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "srt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "subrip", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ass", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "ssa", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgs", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "pgssub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "dvdsub", Method: Encode, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "vtt", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "sub", Method: Embed, DidlMode: null, Language: null, Container: null }, SubtitleProfile { Format: "idx", Method: Embed, DidlMode: null, Language: null, Container: null }] } [2021-11-12 00:57:26.230 -04:00] [INF] User policy for "David". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True [2021-11-12 00:57:26.231 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:26.231 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:26.241 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:26.241 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:26.253 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", Path: "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv", isEligibleForDirectPlay: True, isEligibleForDirectStream: True [2021-11-12 00:57:26.253 -04:00] [INF] Profile: "AndroidTV-ExoPlayer", No video direct play profiles found for "\\192.168.0.10\SHOWS\Invasion (2021)\Season 01\Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" with codec "h264" [2021-11-12 00:57:26.288 -04:00] [INF] Transcoding kill timer stopped for JobId "ac379952e4d848a7a4554e5d5f9bcc9d" PlaySessionId "d4a67cab7cd24efabbd737ba1eb3fb34". Killing transcoding [2021-11-12 00:57:26.288 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/9dfcb9c6612e0ab522b00b7c5ce216bf.mkv" [2021-11-12 00:57:26.321 -04:00] [INF] /usr/bin/ffmpeg -ss 00:03:30.000 -i file:"/home/david/Videos/SHOWS/Invasion (2021)/Season 01/Invasion (2021) - S01E06 - Home Invasion WEBDL-720p.mkv" -map 0:0 -map 0:1 -map -0:s -codec:v:0 libx264 -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,min(1356\,678*dar))/2)*2:trunc(min(max(iw/dar\,ih)\,min(1356/dar\,678))/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset superfast -crf 23 -maxrate 3608508 -bufsize 7217016 -profile:v:0 high -level 41 -x264opts:0 subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 2 -ab 384000 -af "volume=2" -y "/var/lib/jellyfin/transcodes/3eb775bdf9bd856dcf0fb833e3fbafab.mkv" [2021-11-12 00:57:27.539 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/videos/403b5fa9-e7e5-fc8d-4c43-45f344c7ea14/stream.mkv?DeviceId=d04f3aea23877759080e05aeccac9da499f950e2&MediaSourceId=403b5fa9e7e5fc8d4c4345f344c7ea14&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&VideoBitrate=99616000&AudioBitrate=384000&StartTimeTicks=2100000000&PlaySessionId=baa5d663aa644094bac1f6212aba9eca&api_key=ce139a00b81144ec91c71fa92cdcf8ec&SubtitleMethod=Encode&CopyTimestamps=true&RequireAvc=false&Tag=c1fade5f5c186727d339ad268c85fe3d&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&h264-maxrefframes=12&aac-audiochannels=2&mp3-audiochannels=2&TranscodeReasons=AudioCodecNotSupported&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.0.2" in 0:00:01.2422743 with Status Code 200 [2021-11-12 00:57:36.123 -04:00] [INF] Transcoding kill timer stopped for JobId "8f7acb11d99e40a39f4bb89b756df88e" PlaySessionId "89578e75b0ba47b9aaf8bcf9dd50ef72". Killing transcoding [2021-11-12 00:57:36.124 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/b10a49994a0abcc03912ad5e7680edaf.mkv" [2021-11-12 00:57:38.636 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:57:58.645 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:58:18.658 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:58:38.661 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:58:58.692 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:59:18.717 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:59:38.727 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 00:59:58.741 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:00:18.749 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:00:38.761 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:00:59.688 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:01:20.672 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:01:41.673 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:02:01.684 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:02:21.708 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:02:41.728 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:03:02.717 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:03:23.181 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:03:31.588 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:31.589 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-12 01:03:31.590 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:33.597 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:33.597 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-12 01:03:33.597 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:35.618 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:35.618 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-12 01:03:35.618 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:37.630 -04:00] [INF] Defined LAN addresses : "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:37.630 -04:00] [INF] Defined LAN exclusions : "[]" [2021-11-12 01:03:37.631 -04:00] [INF] Using LAN addresses: "[127.0.0.1/8,10.0.0.0/8,172.16.0.0/12,192.168.0.0/16]" [2021-11-12 01:03:43.735 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:03:44.549 -04:00] [INF] FFmpeg exited with code 0 [2021-11-12 01:04:03.755 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:04:24.596 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:04:44.796 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:05:04.813 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:05:24.826 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:05:44.832 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:06:04.841 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:06:24.849 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:06:44.881 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:07:04.942 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:07:24.991 -04:00] [INF] Processing playback tracker : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:07:37.738 -04:00] [INF] Deleting partial stream file(s) "/var/lib/jellyfin/transcodes/3eb775bdf9bd856dcf0fb833e3fbafab.mkv" [2021-11-12 01:07:39.333 -04:00] [INF] Playback stopped reported by app "Android TV" "0.0.0-dev.1" playing " Home Invasion". Stopped at "215963" ms [2021-11-12 01:07:39.349 -04:00] [INF] Playback stop tracker found, processing stop : "d04f3aea23877759080e05aeccac9da499f950e2-bc24de54664546fcb3b47894bdadd5b6-403b5fa9e7e5fc8d4c4345f344c7ea14" [2021-11-12 01:07:39.349 -04:00] [WRN] Slow HTTP Response from "http://192.168.0.10:8096/Sessions/Playing/Stopped" to "192.168.0.2" in 0:00:01.6131522 with Status Code 204 [2021-11-12 01:07:39.349 -04:00] [INF] PlaybackTracker : Adding Stop Event : 11/12/2021 01:07:39 [2021-11-12 01:07:39.349 -04:00] [INF] Saving playback tracking activity in DB [2021-11-12 01:07:39.845 -04:00] [INF] Starting User Changes Sync... [2021-11-12 01:07:39.932 -04:00] [INF] "USERSYNC" User "bc24de54664546fcb3b47894bdadd5b6"("David") posted 2 Updates: "403b5fa9e7e5fc8d4c4345f344c7ea14,d622ae2a73c7d9774162d4f51f7fc2f9" [2021-11-12 01:07:39.932 -04:00] [INF] User Changes Sync Finished Taking "00:00:00.0869634" [2021-11-12 01:08:09.781 -04:00] [INF] WS "127.0.0.1" request [2021-11-12 01:08:12.203 -04:00] [WRN] Slow HTTP Response from "http://localhost:8096/Items/bfcbfef36c8d70d15028a8cad28141d7/Images/Backdrop/0?tag=4ba08fe59413b2f08b4396e2c274d3bc&maxWidth=1920&quality=80" to "127.0.0.1" in 0:00:00.9573679 with Status Code 200

mueslimak3r commented 2 years ago

@Phoenix-004 so by "when the bug happened" do you mean you paused it at that point, and then played, and then it bugged out?

Or did it bug out after seeking without you pausing?

Phoenix-004 commented 2 years ago

@mueslimak3r

No.

  1. You can tell which videos will bug out from the seek bar. For videos that will bug out, the seek bar doesn't work right. If you seek and stop (eg. 14:30), rather than it stay at 14:30 before resuming playback, it will jump back to 0.00, then jump to 14:30 and resume playback.

So I don't have to seek/pause... but seeking lets me know which videos this bug will pop up in.

  1. then when the actual bug happens, the video will randomly jump back to 14:30. If you didn't seek/ pause and just played from the beginning,it would jump back to the beginning.

  2. In addition, on the video launch page (where you see, resume/play, cast, chapters ...etc). These buggy videos will not accurately track playback stop position. So in this case,it would only be showing a resume point at 14:30, even if I had watched up till 33:50.

Phoenix-004 commented 2 years ago

with one of the files, I was watching where this bug happened..I was able to check the client info in the dashboard.

And yes, it was transcoding the file, and the reason for transcoding was "audio format not supported". I was again using Downmix to stereo. If I switch to direct, it doesn't happen.

mueslimak3r commented 2 years ago

I've made a little progress. Basically the way transcode streams work is the jellyfin server sends a video stream URL to the client and it starts streaming it. That URL is tied to the timestamp of the "start"/"resume" time . From then on the player itself keeps track of its progress and informs the server of it. However, if the player crashes, all it has is the URL it got originally that starts the stream at the original time, and it will just reload itself and use that URL. This likely is what you're experiencing.

I found instances where I could make the player crash and it would cause the stream to restart at that time. But its only ever a result of me breaking the code, and for me it never happens in the stable build or these test builds you've tested.

At the end of the day I really can't pin down how to reproduce this on my end. The logs you've provided are server logs and don't tell me much. If you want I can use logs from your client to get a better idea of what's going on.

here is the latest build of my test version, which I've added lots of debug output to: https://github.com/jellyfin/jellyfin-androidtv/suites/4347943097/artifacts/114078390

I assume you've used adb to sideload these debug builds. So this time use adb logcat to capture the debug logs as it runs. Depending on your operating system, how you capture that output will vary. For me on linux I first run adb logcat on its own to make sure it works. Then I run it again and redirect the output to a file: adb logcat 2>&1 > log.txt

Here is a guide that details enabling debug options, connecting with adb, and then using logging: https://stackoverflow.com/a/31436088

And a troubleshooting guide for connection issues: https://stackoverflow.com/a/10006121

Please don't post the debug logs here directly. Use something like pastebin. It's a good idea to do a search and replace in the log for things like your server's URL, and to redact any other sensitive information before uploading anything, and replace it with placeholders like "MYDOMAIN"

mueslimak3r commented 2 years ago

edit: to avoid including extra logs from your system, it would cool to filter by the process ID of the jellyfin client.

You can get this process ID, which is a number, by using adb logcat and looking for the jellyfin related lines, and note the number in the 3rd column from the left.

Then when you dump the log to a txt file you add that process ID as a filter to the logcat command adb logcat --pid=11915 in this case, my pid was 11915.

For the sake of being complete here's another example of how I would write this log to a text file, on linux: adb logcat --pid=11915 2>&1 > log.txt

example of the process ID in the logs, shown in red: image

Phoenix-004 commented 2 years ago

@mueslimak3r

Ok.. using your debug apk... and following most of your instructions.... only the jelyfin info...and I doubt theeris any sensitive data in here. jellyfin debug log

Let me know if thats what you needed.

mueslimak3r commented 2 years ago

This is great, thanks. I already see a couple things to check out. Here's a summery of what I saw from the logs. To me, the instances of "onStop" being caught could be you stopping it or it bugging out, I can't tell just from the logs. That's why I'm posting this summery.

1) So my impressions from these logs are you start playback at around time 7:08. The first "play" log isn't there so I guess. 2) At about 7:20 you try to seek forward to 8:30.

3) t looks like the seek worked and it kept playing from 8:30. It probably did that thing where the seekbar shows it at 0:00 for a second. My understanding is that's just how it looks when you transcode.

4) Then you pause right after seeking. 5) Now right after you pause, like 3 seconds later, the player catches an event that it should stop, "onStop". Do you remember if you pressed the "back button" or anything like that? If not then this could indicate the bug.

6) Then about 10 minutes after that you press play, and it attempts to resume from that same timestamp. Based on the timestamps in the log that looks like it did play from that time, please let me know if that's incorrect.

7) right after starting playback again you pause 8) and then a few seconds later, just like # 5, onStop is caught and as far as the player and server are concerned, you are no longer playing media.

8) about 1.5 minutes later you start playback again from that timestamp it stopped at, and it looks like it works okay. 9)Then you play media for about 2 minutes. At that point I do see something weird in the logs like it thinks its starting playback all over again. That's at 12:18pm.

10) then from 12:18-12:24pm it plays, and then the same thing as # 9 happens. 11) media plays from 12:24-12:32pm, and then you pause. You resume a few seconds later and it looks like no issues there.

12) you then pause a few minutes later, and then a few seconds later another onStop is caught. This time I assume it was you pressing back since this is the end of the log.

Phoenix-004 commented 2 years ago

@mueslimak3r

Damn.. you could tell that from logs??? Like a fly on my wall in my house or something lol. Great work.

Yes, you are right on the money on everything. Yes initially that was me going back out of the app when I was still trying to figure out the log thing and isolating only the jellyfin logs.

From (5) all the way to (11)... that it. That's what happens. I was messing around with the pause and seeks to see if I can get something to show up as to how "I know" is gonna bug out. And eventually,I just let it play, and whenever it jumped back, I didn't try and see forward but just let it continue playing until it happened at least twice.

mueslimak3r commented 2 years ago

Okay so addressing the low hanging fruit first, here's a new build with a small fix to the system that monitors the playback state & progress. It looks like that wasn't working correctly for you so maybe this will change something.

I appreciate you taking the time to troubleshoot and test these builds :)

new build: https://github.com/jellyfin/jellyfin-androidtv/suites/4352297457/artifacts/114227431

Phoenix-004 commented 2 years ago

Ok cool. Wil install, and give you feed back.

And No problem, you guys are the ones doing al the real work.

mueslimak3r commented 2 years ago

new build with a few more potential fixes: https://github.com/jellyfin/jellyfin-androidtv/suites/4352962410/artifacts/114251908

Phoenix-004 commented 2 years ago

@mueslimak3r

jellyfin logcat 2.docx Just tried the previous build. Not the latest one you just posted.

It happened again, took a log... dunno if I did something wrong, but this logcat seems a lot busier than the other one.

I willtry out the latest build and get back to you tomroow.

mueslimak3r commented 2 years ago

Yeah you logged the wrong PID. Next time look for a line with the text "mExoPlayer time got" since that only comes from jellyfin

Phoenix-004 commented 2 years ago

ok...will try that on the new build you just put up.

Phoenix-004 commented 2 years ago

@mueslimak3r OK. Here's the log with the latest build. And itstill happened. Jellyfin debug log 3.docx

mueslimak3r commented 2 years ago

I found something potentially useful. On my end the seekbar briefly jumping back to 0 when seeking is fixed by this change so that's a good sign.

Fingers crossed this might actually be it: https://github.com/jellyfin/jellyfin-androidtv/suites/4355136418/artifacts/114331458

Phoenix-004 commented 2 years ago

Installing and testing the latest build now.

Phoenix-004 commented 2 years ago

jellyfin debug log 4.txt

It happned again on thelatest build. This time though it was a little diferent.

  1. The seekbar resetting to 0.00 afetr seeking is fixed.
  2. Everything seemedfine fr the first 20or sominutes,then it started happenning,then i started takinga log... resumed playback andit happens in uder 10mins...and seems to have ben happening more frequently since then.
  3. During playback,I got anotificationon scren forlike2 orso seconds,saying something about Trial something,it diesappeared beforei could readit. And the shortlyafter,playback froze (blak screen),I used the backbutton and went back to the media landing page, then resumed play back and it played again. Unfortunately I was not taking alog whenthis happened.
  4. If checking the log, look at the last 10-15mns.thats whenit happened again.