Server Version#: 1.31.1.6782
Player Version#: 9.17.0.38861 (Taken from my android phone)
I’m having a rather odd issue, in that when I try to play a file lately via a Plex Android client the server proceeds to read through the entire file and then plays the file. Now, I’m not quite sure why this is happening, but I’m hoping to get some light shed on this.
In my case, I have a cloud provider mounted via rclone that houses my media and when I try to play a file this is what I get in my rclone logs
You can see that the file is probed and then proceeds to read through the entire file and only then does it play the file correctly. I can reproduce this on all my android devices; Pixel phones, Fire Tables, and Fire TV devices. I can also see it with my Vizio and Roku TVs.
Another reproducible part of this is when this is happening, if I hit back to cancel playing the file, and then play the same file again, sometimes it will load up just fine.
I tried to get the matching Plex log for this, but it looks like it has been rotated out.
UPDATE: It seems like this issue only exists if I’m direct playing the file. If I force it to transcode the video then it does not seem to have the same issue. It is like direct play does not let the server figure out where the user left off and instead just streams the entire file to the user as fast as the network connection will let it and lets the client figure out when it gets to the resume point.
I think this is an rclone issue. The Android app wants to analyze the file which includes reading info from the beginning and a little at the end of a file. Sounds like rclone is grabbing the entire file to allow access to this info instead of just passing the portions needed. Plex does not support using cloud drives so it’s unknown/unexpected what rclone or other apps that provide cloud access will do.
I’ll capture a log of this command so you can see the difference. Rclone uses fuse so really there should not be any “cloud” vs “local” issues as that is abstracted away. Not to mention, the other post that I linked is not a cloud storage situation.
#The following are opening up the file for reading
2023/03/10 01:55:56 DEBUG : /: Lookup: name="folder1"
2023/03/10 01:55:56 DEBUG : /: >Lookup: node=folder1/, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/: Attr:
2023/03/10 01:55:56 DEBUG : folder1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwx---, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/: Lookup: name="folder2"
2023/03/10 01:55:56 DEBUG : folder1/: >Lookup: node=folder1/folder2/, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/: Attr:
2023/03/10 01:55:56 DEBUG : folder1/folder2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwx---, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/: Lookup: name="folder3"
2023/03/10 01:55:56 DEBUG : folder1/folder2/: >Lookup: node=folder1/folder2/folder3/, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/: Attr:
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwx---, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/: Lookup: name="file.mkv"
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/: >Lookup: node=folder1/folder2/folder3/file.mkv, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: Attr:
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: >Attr: a=valid=1s ino=0 size=2822291340 mode=-rw-rw----, err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: Open: flags=OpenReadOnly
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: Open: flags=O_RDONLY
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: >Open: fd=folder1/folder2/folder3/file.mkv (r), err=<nil>
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: >Open: fh=&{folder1/folder2/folder3/file.mkv (r)}, err=<nil>
2023/03/10 01:55:56 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Flush:
2023/03/10 01:55:56 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: >Flush: err=<nil>
#Here is where the file is finally open, having a descriptor and the first read is initiated
#It looks like it is trying to read from an initial offset of 1228800000 (The product of me opening the file with 4k blocksize and skipping ahead 300000 blocks)
2023/03/10 01:55:56 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Read: len=4096, offset=1228800000
2023/03/10 01:55:56 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.openRange at 0 length 134217728
#Here the actual seek takes place
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ReadFileHandle.seek from 0 to 1228800000 (fs.RangeSeeker)
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.RangeSeek from 0 to 1228800000 length -1
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at -1 length 4096 chunkOffset 1228800000 chunkSize 134217728
#Here we are starting to read from the expected point 1228800000
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.openRange at 1228800000 length 134217728
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at 1228804096 length 8192 chunkOffset 1228800000 chunkSize 134217728
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: >Read: read=4096, err=<nil>
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at 1228812288 length 16384 chunkOffset 1228800000 chunkSize 134217728
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at 1228828672 length 32768 chunkOffset 1228800000 chunkSize 134217728
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Read: len=16384, offset=1228804096
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: >Read: read=16384, err=<nil>
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at 1228861440 length 65536 chunkOffset 1228800000 chunkSize 134217728
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Read: len=32768, offset=1228820480
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Read: len=65536, offset=1228853248
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: >Read: read=32768, err=<nil>
2023/03/10 01:55:57 DEBUG : folder1/folder2/folder3/file.mkv: ChunkedReader.Read at 1228926976 length 131072 chunkOffset 1228800000 chunkSize 134217728
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: Read: len=131072, offset=1228918784
2023/03/10 01:55:57 DEBUG : &{folder1/folder2/folder3/file.mkv (r)}: >Read: read=65536, err=<nil>
I don’t know what any of that is. Sorry, not a Linux guy. Can you reproduce the issue and get me your server and Android logs so I can see what is being requested and what PMS is returning?
Sure thing, would you prefer logs directly from the android device or the log to server option, assuming the later is still an option.
The log above is labeled to show what rclone is doing, dd basically just reads byte for byte from the file in quesiton. You can see that when dd is called it opens the file and then jumps to read from the offset–the offset in this case is simulating reading from the middle of a file/movie–which Plex does not seem to do. I chose dd as it is a very simple utility that is used for raw reads/writes all the time in Linux.
In the first log, which is in the first post, you can see where Plex opens the file and then proceeds to read through the full file to get to the seek/resume point. In the first log it also looks like Plex is probing as expected, just like mediainfo and the like do, you can see where each of those ends as I put a few blank lines at the end of each time the file is closed.
I have managed to track this down to something weird when cloudflare is used, for now I’m just forgoing it and all is well and the moment I turn it on I get the same issue. Perhaps they are getting a bit more aggressive on it being used with plex.
