Server Version#: 1.18.7.2457
Player Version#: 4.25.2 (Samsung Tizen version 3.0)
I recently moved my PMS into Docker on my Synology and have been having a lot of trouble when seeking into videos or resuming playback from a point within the video. At times it does work, but I often get an error stating that the video format is not supported… even though it was playing fine minutes earlier.
Logs uploaded. Plex Media Server Logs_2020-03-06_20-30-50.zip (5.7 MB)
From your logs, I can clearly see the CPU is busy.
It’s busy indexing media.
You’re not able to transcode anything because you didn’t create the container correctly.
I’m going ask this because I care about the experience you’re about to have.
I am genuinely asking this as a “Why do it just because you can?” (the Jurassic Park problem)
Mar 06, 2020 20:27:52.943 [0x7f5bfb7fe700] DEBUG - TPU: hardware transcoding: using hardware decode accelerator vaapi
Mar 06, 2020 20:27:52.943 [0x7f5bfb7fe700] DEBUG - [Universal] Using local file path instead of URL: /volume1/Perry/Perry/Videos/TV Shows/Top Gear/Season 28/Top.Gear.S28E06.1080p.HDTV.H264-MTB[rarbg].mkv
Mar 06, 2020 20:27:52.943 [0x7f5bfb7fe700] DEBUG - TPU: hardware transcoding: zero-copy support present
Mar 06, 2020 20:27:52.943 [0x7f5bfb7fe700] DEBUG - TPU: hardware transcoding: using zero-copy transcoding
Mar 06, 2020 20:27:52.943 [0x7f5bfb7fe700] DEBUG - Codecs: hardware transcoding: testing API vaapi
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x32315659 -> yuv420p.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x30323449 -> yuv420p.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x3231564e -> nv12.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x32595559 -> yuyv422.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x59565955 -> uyvy422.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x48323234 -> yuv422p.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x58424752 -> rgb0.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x58524742 -> bgr0.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Format 0x30313050 -> p010le.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Created surface 0x4000000.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - [FFMPEG] - Direct mapping possible.
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - TPU: hardware transcoding: final decoder: vaapi, final encoder: vaapi
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] ERROR - Error creating directory "/config/transcode": Permission denied
Mar 06, 2020 20:27:52.944 [0x7f5bfb7fe700] DEBUG - Job running: EAE_ROOT='/tmp/pms-0d87bb00-faa1-4b7a-93fc-13e2a686517d/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/0bc617e-2965-linux-x86_64/' XDG_CACHE_HOME='/config/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources'
Thanks @ChuckPa, I know you care about my experience and I greatly appreciate it!
I didn’t notice that permissions issue, I will get that fixed right away. Interestingly, I actually have been able to transcode quite successfully and the use of hardware transcoding has taken significant load off away from my CPU. For the most part, videos play quite well…so I found it very odd that the occasional seek/restart gave me problems.
Re: Docker - I actually did have the native Synology PMS installed but I found it quite annoying to update the package and Docker gives me a way of doing it automatically (i.e. Watchdog). The Synology web UI is extremely poor on a mobile device and I’m not often at a laptop. I’d happily go back to the native install if Synology would allow you to post the 64-bit package and keep it updated.
Back to this issue specifically, I will fix that permissions issue and keep an eye on the CPU usage if/when this occurs but I still feel like we may be looking at a bug that could be resolved/improved:
Thanks again for your help!
If PMS is yielding errors during seeking / not supported is something I can test on any other Linux system.
I would need a sample of the file which will recreate it
-and/or-
A Steps-to-reproduce procedure which is as detailed as necessary.
Synology’s web UI, on a mobile device, is indeed a painful experience.
Their mobile apps address that problem extremely well.
We’ve been working with them to keep PMS more updated in Package Center.
If they do , DSM’s automatic update mechanism will keep your Syno up to date as well – automagically
Thanks Chuck. As I mentioned, it is not easily reproducible so I was hoping that the logs I supplied would give some indication of what happened. Even for the same file it sometimes happens and sometimes does not.
Re: Synology…I don’t believe the mobile app allows me to upload a new custom-package right? I agree that once the 64-bit PMS package is available it will be kept up-to-date.
Thanks again
This specific file (Top Gear episode) is corrupt. Playing it on a Windows PC with MPC-HC doesnt even have video, only audio. Plex is somehow able to transcode it but becomes erratic at some points in the video.
Context please? Did you post in the wrong thread?
No, i had the same issue as @krugster and found this thread searching the file name. (File name is in the piece of the logging you posted)
I think he was unlucky to play this problematic file just after changing his setup. So better test with other video’s for troubleshooting this.
FWIW, for me this was happening on many different videos, the Top Gear one was just the latest I found it on.
Plex Media Server Logs_2020-03-12_20-43-36.zip (6.0 MB) @ChuckPa I ran into this again.
New logs uploaded, thanks for your help!
I can appreciate that the CPU might be underpowered, but I would expect Plex to a) show a more accurate and consistent error and b) to just continue processing even if it took a little longer. Playback in general works fine, why can’t I seek?
Perry
Do you have a timestamp for me?
I see where a seek past the end-of-file was performed.
Signed-in
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Asked for segment 120 from session.
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - We're in a seek: asked for 120, min/max available was 0/106
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Segment #120 WON.
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Killing job.
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Signalling job ID 17177 with 9
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Job was already killed, not killing again.
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - Stopping transcode session edfrb9ensmoyldij0hptqzgs
Mar 12, 2020 20:36:00.770 [0x7f96ab5dc700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 17177 is -9 (signal: Killed)
Mar 12, 2020 20:36:00.860 [0x7f96797fa700] DEBUG - Starting a transcode session edfrb9ensmoyldij0hptqzgs at offset 120.0 (state=3)
Mar 12, 2020 20:36:00.878 [0x7f96797fa700] DEBUG - TPU: hardware transcoding: using hardware decode accelerator vaapi
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [Universal] Using local file path instead of URL: /volume1/Perry/Perry/Videos/TV Shows/Ray Donovan/Season 07/Ray.Donovan.S07E09.PROPER.1080p.WEB.h264-TBS[rarbg].mkv
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - TPU: hardware transcoding: zero-copy support present
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - TPU: hardware transcoding: using zero-copy transcoding
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - Codecs: hardware transcoding: testing API vaapi
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x32315659 -> yuv420p.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x30323449 -> yuv420p.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x3231564e -> nv12.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x32595559 -> yuyv422.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x59565955 -> uyvy422.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x48323234 -> yuv422p.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x58424752 -> rgb0.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x58524742 -> bgr0.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Format 0x30313050 -> p010le.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Created surface 0x4000000.
Mar 12, 2020 20:36:00.879 [0x7f96797fa700] DEBUG - [FFMPEG] - Direct mapping possible.
Mar 12, 2020 20:36:00.880 [0x7f96797fa700] DEBUG - TPU: hardware transcoding: final decoder: vaapi, final encoder: vaapi
Yeah that would be about the right timeline. The second failure was less than a couple minutes before the end of the log file, the first one would be only a couple minutes before that.
Do you see two separate errors?
Thanks!
Thanks.
When I see it seek off the end of the file like that, the first question I need to ask is “Did you change the quality (size) of the file since it was originally scanned?”
If the answer is “yes”, Did you “Analyze” it again so Plex knows how long it really is?
I did not change it since acquiring it originally, and I do have plex regularly analyse my media as part of the scheduled tasks.
These issues have happened on a number of different files so I would be surprised if they all had bad lengths/offsets.
Do you see the same end-of-file issue in the first set of logs I uploaded as well? Could it be a bug in the client (Samsung Tizen app)?
Thanks
Good morning @ChuckPa
I did a bit of digging into the logs, but I admit I’m not exactly sure what I found 
I do see that message of seeking past the end of the segment, but from what I can tell it’s just referring to what has already been transcoded. Later on, the logs show the same file sending segments well beyond 120:
Mar 12, 2020 20:36:00.744 [0x7f96797fa700] DEBUG - We're in a seek: asked for 120, min/max available was 0/106
...
Mar 12, 2020 20:36:00.881 [0x7f96a3fff700] DEBUG - Streaming Resource: Resetting play progress due to seek
...
Mar 12, 2020 20:36:15.841 [0x7f965b7f6700] DEBUG - Transcoder segment range: 116 - 122 (122)
Mar 12, 2020 20:36:15.866 [0x7f96797fa700] DEBUG - Returning segment 121 from session
However, here are some interesting bits:
Mar 12, 2020 20:39:43.317 [0x7f965aff5700] DEBUG - Asked for segment 156 from session.
Mar 12, 2020 20:39:43.317 [0x7f965aff5700] DEBUG - Returning segment 156 from session
Mar 12, 2020 20:39:43.317 [0x7f965aff5700] ERROR - Couldn't find the file to stream: /config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/init-stream0.m4s,/config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/chunk-stream0-00157.m4s
Mar 12, 2020 20:39:43.318 [0x7f96a37fe700] DEBUG - Completed: [10.0.0.2:35869] 404 GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP 0ms 331 bytes (pipelined: 10)
Mar 12, 2020 20:39:43.356 [0x7f96557ea700] DEBUG - HTTP 200 response from GET https://plex.tv/api/v2/server/access_tokens?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Mar 12, 2020 20:39:43.358 [0x7f96557ea700] DEBUG - MyPlex: updating with 10 access tokens
Mar 12, 2020 20:39:43.360 [0x7f965cff9700] DEBUG - HTTP requesting GET https://plex.tv/media/providers?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Mar 12, 2020 20:39:43.485 [0x7f96797fa700] DEBUG - Request: [10.0.0.2:35870 (Subnet)] GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP Signed-in
Mar 12, 2020 20:39:43.485 [0x7f96797fa700] DEBUG - Asked for segment 156 from session.
Mar 12, 2020 20:39:43.485 [0x7f96797fa700] DEBUG - Returning segment 156 from session
Mar 12, 2020 20:39:43.485 [0x7f96797fa700] ERROR - Couldn't find the file to stream: /config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/init-stream0.m4s,/config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/chunk-stream0-00157.m4s
Mar 12, 2020 20:39:43.485 [0x7f96a37fe700] DEBUG - Completed: [10.0.0.2:35870] 404 GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP 0ms 331 bytes
Mar 12, 2020 20:39:43.564 [0x7f9678ff9700] DEBUG - Transcoder segment range: 116 - 251 (251)
Mar 12, 2020 20:39:43.635 [0x7f965b7f6700] DEBUG - Request: [10.0.0.2:35871 (Subnet)] GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP Signed-in
Mar 12, 2020 20:39:43.635 [0x7f965b7f6700] DEBUG - Asked for segment 156 from session.
Mar 12, 2020 20:39:43.635 [0x7f965b7f6700] DEBUG - Returning segment 156 from session
Mar 12, 2020 20:39:43.635 [0x7f965b7f6700] ERROR - Couldn't find the file to stream: /config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/init-stream0.m4s,/config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/chunk-stream0-00157.m4s
Mar 12, 2020 20:39:43.636 [0x7f96a2ffd700] DEBUG - Completed: [10.0.0.2:35871] 404 GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP 0ms 331 bytes
Mar 12, 2020 20:39:43.740 [0x7f96797fa700] DEBUG - Request: [10.0.0.2:35872 (Subnet)] GET /video/:/transcode/universal/dash/mmo9a08dk8svpldiu0saj49k/0/156.m4s (11 live) TLS GZIP Signed-in
Mar 12, 2020 20:39:43.741 [0x7f96797fa700] DEBUG - Asked for segment 156 from session.
Mar 12, 2020 20:39:43.741 [0x7f96797fa700] DEBUG - Returning segment 156 from session
Mar 12, 2020 20:39:43.741 [0x7f96797fa700] ERROR - Couldn't find the file to stream: /config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/init-stream0.m4s,/config/tmp_transcoding/Transcode/Sessions/plex-transcode-mmo9a08dk8svpldiu0saj49k-ba88a7d6-7e56-4e97-a9ce-069c74b7e58d/chunk-stream0-00157.m4s
Mar 12, 2020 20:43:00.736 [0x7f965aff5700] DEBUG - Request: [127.0.0.1:52676 (Loopback)] PUT /video/:/transcode/session/t1eq8ywd39g22o6rtc4ox75u/89a26f0a-6225-4a44-934d-3e6d187d8e1e/progress?duration=3036.480000 (11 live) Signed-in Token (krugster) (range: bytes=0-)
Mar 12, 2020 20:43:00.737 [0x7f96a2ffd700] DEBUG - Completed: [127.0.0.1:52676] 204 PUT /video/:/transcode/session/t1eq8ywd39g22o6rtc4ox75u/89a26f0a-6225-4a44-934d-3e6d187d8e1e/progress?duration=3036.480000 (11 live) 0ms 203 bytes (pipelined: 10) (range: bytes=0-)
Mar 12, 2020 20:43:00.799 [0x7f96797fa700] ERROR - [Transcoder] Could not write header for output file #0 (incorrect codec parameters ?): No such file or directory
Mar 12, 2020 20:43:00.800 [0x7f969affd700] ERROR - [Transcoder] Error initializing output stream 0:1 --
Mar 12, 2020 20:43:00.833 [0x7f96ab5dc700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 18254 is 1 (failure)
Any thoughts on where those two errors might be coming from and what, if anything, I could do to work around them? Or are they bugs within the server? I appreciate it may very well be due to CPU starvation (though I’m skeptical) but surely there’s something that PMS can do better to handle it?
Thanks!
I am experiencing the exact same issue. It frequently happens when I seek 10 seconds backwards. I get these errors in the logs:
ERROR - Couldn't find the file to stream: /var/lib/plex/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-m40k56ufy9j8bgj9jzwndfo6-b9db15dd-19ef-415f-bed0-84305b70b77c/init-stream1.m4s,/var/lib/plex/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-m40k56ufy9j8bgj9jzwndfo6-b9db15dd-19ef-415f-bed0-84305b70b77c/chunk-stream1-00521.m4s
Docker is entirely different than the native Synology application.
Please create a fresh thread and tag it server-docker
