Sudden buffering when streaming high bitrate 4k content on Plex

Engelbrecht · December 15, 2020, 11:32pm

What is the problem you are having with rclone?

Plex starts buffering when playing 4k high bitrate content after a few seconds

What is your rclone version (output from `rclone version`)

rclone v1.53.3

os/arch: linux/amd64
go version: go1.15.5

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 18.04.5 LTS (GNU/Linux 4.15.0-128-generic x86_64)
Hardware:
128 GB RAM
CPU: Intel Core i7-8700 hexacore
Disk pace: 2 TB NVME SSD

no docker or something like that for plex

Which cloud storage system are you using? (eg Google Drive)

Google Drive

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

[Unit]
Description=Mount and cache Google drive to /media/PlexMedia_crypt
After=syslog.target local-fs.target network.target
[Service]
Environment=RCLONEHOME=/home/plexuser/.config/rclone
Environment=MOUNTTO=/media/PlexMedia_crypt
Environment=LOGS=/home/plexuser/logs
Environment=UPLOADS=/home/plexuser/uploads
Type=simple
User=root
ExecStartPre=/bin/mkdir -p ${MOUNTTO}
ExecStartPre=/bin/mkdir -p ${LOGS}
ExecStartPre=/bin/mkdir -p ${UPLOADS}
ExecStart=/usr/bin/rclone mount \
  --log-file ${LOGS}/plexmedia_rclone.log \
  --log-level INFO \
  --umask 002 \
  --allow-non-empty \
  --allow-other \
  --dir-cache-time=160h \
  --drive-chunk-size=512M \
  --buffer-size=512M \
  --vfs-read-chunk-size=128M \
  --vfs-read-chunk-size-limit 2G \
  --vfs-cache-max-age=72h \
  --vfs-cache-mode=writes \
  --cache-dir ${UPLOADS} \
  --config ${RCLONEHOME}/rclone.conf \
  PlexMedia_crypt: ${MOUNTTO}
ExecStop=/bin/fusermount -u -z ${MOUNTTO}
ExecStop=/bin/rmdir ${MOUNTTO}
Restart=always
[Install]
WantedBy=multi-user.target

The rclone config contents with secrets removed.

[PlexMedia_crypt]
type = crypt
remote = Gdrive:/PlexMedia_crypt
filename_encryption = standard
directory_name_encryption = true
password = ****

First of all, i want to let you know that I am aware of plenty similar topics. However, since my current problem arose some days ago, I'm not sure whether it is a new problem regarding rclone, my hardware or my mount settings.
Furthermore, it is important to note that I never had any problems streaming high bitrate 4k content (>60 mb/s)using my setup until some days ago.

Media Player is the Nvidia Shield Pro 2019 connected via ethernet (500 MBit bandwidth connection).

What I did/check up to now?

no ISP problems (speed test passed positive = 500 mbit constant)
server side test (speed test passed positive = 1Gbit constant)
changing the cables

Current issue/scenario:
When i start streaming some high bitrate 4k content plex starts buffering after a few seconds of playing. Then the video runs a few more seconds and starts buffering again etc. Again, i noticed this behavior since only some days. Up to now there was no problem, yet.
Of course, currently I'm not sure whether the problem comes from plex itself, the content I am streaming, rclone or a combination of all those factors.

My final question is:
What's wrong with my setup? I have plenty of RAM (128 GB) + 2 TB disk space, so is there a possibility to cache more parts of the video feed on the server to avoid buffering?

I already tested this --vfs-cache-mode full option... the file size is around 80GB large. So loading the video takes years but then plays smooth.
I hope that there is a reasonable middle course (i certainly do not want to preload the full movie, but it may take some seconds to start it when preloading some GB)

Thank you

asdffdsa · December 15, 2020, 11:43pm

hello and welcome to the forum,

does the file system support of the cache support sparse files?
if true, then rclone should not be downloading the entire file, just the chunks as needed.

Engelbrecht · December 15, 2020, 11:50pm

You mentioned that the allow-non-empty option is not recommended. Okay, I'll take that off.
How can I check whether my file system supports cash sparse files? (Sorry but I have no clue.. i only saw that it was also mentioned in the rclone documentation)

asdffdsa · December 15, 2020, 11:54pm

i removed my comment about allow-non-empty.
since the service file is creating the mount point folder each time, then the folder will be empty.
so that flag is not really a problem but still i would remove it.

as for sparse file, i know how to tell on windows os but sure for linux
what is the file system for the cache?

maybe this will help, else one of our rclone experts will help out soon, like @Animosity022
https://en.wikipedia.org/wiki/Sparse_file

Animosity022 · December 16, 2020, 1:04am

Unless you are using some odd file system, you'd have to include a debug log with full as that's not normal.

You should just remove all of that and use the defaults with full and test / post a debug log.

You'd want to validate you aren't transcoding and are direct playing/streaming.

Engelbrecht · December 16, 2020, 11:45am

Thank you @Animosity022 for your quick assistance
I did my homework and tested your recommendations with the DEBUG option. Unfortunately, I'm not sure how much you need to see from it. So i cleared my past logs and started with a fresh log.
Please, apologize if I missed out something or made a mistake. Note that I hide original directory or file names as well as the google API key link. (if you see any directory name errors, it is because I renamed it for posting it public)

By the way: changing these settings didn't have any effect. Video loads for minutes until I gave up after 5-10 mins.

Here you find it (i hope that spoilers work in the forum)

2020/12/16 11:13:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:14:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:15:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:16:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:17:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:18:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:19:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:20:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:21:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:22:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:23:47 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:24:32 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/usr/bin/rclone" "mount" "--log-file" "/home/plexuser/logs/plexmedia_rclone.log" "--log-level" "DEBUG" "--umask" "002" "--allow-other" "--dir-cache-time=160h" "--drive-chunk-size=512M" "--vfs-cache-max-age=72h" "--vfs-cache-mode" "full" "--cache-dir" "/home/plexuser/uploads" "--config" "/home/plexuser/.config/rclone/rclone.conf" "PlexMedia_crypt:" "/media/PlexMedia_crypt"]
2020/12/16 11:24:32 DEBUG : Using config file from "/path_to/rclone.conf"
2020/12/16 11:24:32 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:32 DEBUG : pacer: Rate limited, increasing sleep to 1.919704321s
2020/12/16 11:24:32 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:32 DEBUG : pacer: Rate limited, increasing sleep to 2.443826505s
2020/12/16 11:24:34 DEBUG : pacer: low level retry 3/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:34 DEBUG : pacer: Rate limited, increasing sleep to 4.72776705s
2020/12/16 11:24:41 DEBUG : pacer: Reducing sleep to 0s
2020/12/16 11:24:42 DEBUG : Encrypted drive 'PlexMedia_crypt:': Mounting on "/media/PlexMedia_crypt"
2020/12/16 11:24:42 DEBUG : vfs cache root is "/home/plexuser/uploads/vfs/PlexMedia_crypt"
2020/12/16 11:24:42 DEBUG : Adding path "vfs/forget" to remote control registry
2020/12/16 11:24:42 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/12/16 11:24:42 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/12/16 11:24:42 DEBUG : : Root: 
2020/12/16 11:24:42 DEBUG : : >Root: node=/, err=<nil>
2020/12/16 11:24:42 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: updateTime: setting atime to 2020-12-15 13:49:58.750611342 +0100 CET
2020/12/16 11:24:42 INFO  : Cleaned the cache: objects 7 (was 0), total size 97.790G (was 0)
2020/12/16 11:24:48 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:24:48 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:24:48 DEBUG : Filme/: Attr: 
2020/12/16 11:24:48 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:24:48 DEBUG : Filme/: Lookup: name=".grab"
2020/12/16 11:24:50 DEBUG : Filme/: >Lookup: node=<nil>, err=no such file or directory
2020/12/16 11:24:50 DEBUG : /: Lookup: name="Serien"
2020/12/16 11:24:50 DEBUG : /: >Lookup: node=Serien/, err=<nil>
2020/12/16 11:24:50 DEBUG : Serien/: Attr: 
2020/12/16 11:24:50 DEBUG : Serien/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:24:50 DEBUG : Serien/: Lookup: name=".grab"
2020/12/16 11:24:51 DEBUG : Serien/: >Lookup: node=<nil>, err=no such file or directory
2020/12/16 11:25:42 DEBUG : Google drive root 'PlexMedia_crypt': Checking for changes on remote
2020/12/16 11:25:42 INFO  : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:25:46 DEBUG : /: Attr: 
2020/12/16 11:25:46 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Attr: 
2020/12/16 11:25:48 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: ReadDirAll: 
2020/12/16 11:25:48 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Backup"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Backup/, err=<nil>
2020/12/16 11:25:48 DEBUG : Backup/: Attr: 
2020/12/16 11:25:48 DEBUG : Backup/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:48 DEBUG : Filme/: Attr: 
2020/12/16 11:25:48 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:48 DEBUG : Filme/: Attr: 
2020/12/16 11:25:48 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Serien"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Serien/, err=<nil>
2020/12/16 11:25:48 DEBUG : Serien/: Attr: 
2020/12/16 11:25:48 DEBUG : Serien/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Serien"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Serien/, err=<nil>
2020/12/16 11:25:48 DEBUG : Serien/: Attr: 
2020/12/16 11:25:48 DEBUG : Serien/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:48 DEBUG : /: Lookup: name="Serverbackup"
2020/12/16 11:25:48 DEBUG : /: >Lookup: node=Serverbackup/, err=<nil>
2020/12/16 11:25:48 DEBUG : Serverbackup/: Attr: 
2020/12/16 11:25:48 DEBUG : Serverbackup/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:56 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:56 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/: Attr: 
2020/12/16 11:25:56 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:56 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:56 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/: Attr: 
2020/12/16 11:25:56 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/: Lookup: name="Abenteuer & Fantasy"
2020/12/16 11:25:56 DEBUG : Filme/: >Lookup: node=Filme/Abenteuer & Fantasy/, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/: Attr: 
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/: Lookup: name="4k_movie_directory"
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Attr: 
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:56 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Lookup: name="4k"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: Lookup: name="4k_movie_directory"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Lookup: name="4k_movie.mkv"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: >Attr: a=valid=1s ino=0 size=131956986352 mode=-rw-rw-r--, err=<nil>
2020/12/16 11:25:57 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:57 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : /: Lookup: name="Filme"
2020/12/16 11:25:57 DEBUG : /: >Lookup: node=Filme/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/: Lookup: name="Abenteuer & Fantasy"
2020/12/16 11:25:57 DEBUG : Filme/: >Lookup: node=Filme/Abenteuer & Fantasy/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/: Lookup: name="4k_movie_directory"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Lookup: name="4k"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: Lookup: name="4k_movie_directory"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: Lookup: name="4k_movie_directory.mkv"
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/: >Lookup: node=Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: Attr: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: >Attr: a=valid=1s ino=0 size=131956986352 mode=-rw-rw-r--, err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: Open: flags=OpenReadOnly
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: Open: flags=O_RDONLY
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: >Open: fd=Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv (rw), err=<nil>
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv: >Open: fh=&{Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv (rw)}, err=<nil>
2020/12/16 11:25:57 DEBUG : &{Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv (rw)}: Flush: 
2020/12/16 11:25:57 DEBUG : &{Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv (rw)}: >Flush: err=<nil>
2020/12/16 11:25:57 DEBUG : &{Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv (rw)}: Release: 
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv(0xc00013e660): RWFileHandle.Release closing
2020/12/16 11:25:57 DEBUG : Filme/Abenteuer & Fantasy/4k_movie_directory/4k_movie.mkv(0xc00013e660): close:

What I see is that there is something odd regarding the API key, isn't it? When I set up rclone and the mount at the very first time, I created a unique API key. Maybe I did something wrong or it expired for any reason. I have no clue.
I also used vnstat --live (command line tool) to see whether the Server is gathering any data from the drive.
It states that the server is receiving packages at a bandwidth of around 1 Gbit. Accordingly, the speed seems to be fine.

You was further stating that until I don't use an odd file system, --vfs-cache-mode full should work.
So that made me to check what kind of file system I use on my machine:

Filesystem       Type         Size  Used Avail Use% Mounted on
udev             devtmpfs      32G     0   32G   0% /dev
tmpfs            tmpfs        6.3G  864K  6.3G   1% /run
/dev/md2         ext4         906G  157G  703G  19% /
tmpfs            tmpfs         32G   12K   32G   1% /dev/shm
tmpfs            tmpfs        5.0M     0  5.0M   0% /run/lock
tmpfs            tmpfs         32G     0   32G   0% /sys/fs/cgroup
/dev/md1         ext3         488M  116M  347M  26% /boot
PlexMedia_crypt: fuse.rclone  1.0P   41T  1.0P   4% /media/PlexMedia_crypt
tmpfs            tmpfs        6.3G     0  6.3G   0% /run/user/1000

I certainly do not know what did you mean by odd file system, but here you can see it.

Please let me know if I missed something or if you need further information.

Thank you

Animosity022 · December 16, 2020, 12:28pm

Engelbrecht:

2020/12/16 11:24:32 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:32 DEBUG : pacer: Rate limited, increasing sleep to 1.919704321s
2020/12/16 11:24:32 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:32 DEBUG : pacer: Rate limited, increasing sleep to 2.443826505s
2020/12/16 11:24:34 DEBUG : pacer: low level retry 3/10 (error Get https://www.googleapis.com/drive/***: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/12/16 11:24:34 DEBUG : pacer: Rate limited, increasing sleep to 4.72776705s
2020/12/16 11:24:41 DEBUG : pacer: Reducing sleep to 0s

Those are DNS errors on your server and should be fixed.

The beginning of the debug log is what is needed as that shows the version/mount options/etc.

The cache is probably there so any ext4 would work fine as most recent file systems do.

Mine happens to be XFS but ext4 is just fine as well.

felix@gemini:~$ mount | grep cache
/dev/sda1 on /cache type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=32k,noquota)

If you can share the start of the debug log from the start, that would be superb.

Engelbrecht · December 16, 2020, 12:58pm

Thank you very much, again. In the meantime I noticed some interesting things I want to share... what, in fact, confuses me and what could make sense if I got you right... but first of all, I want to answer your question:

Unfortunately, I fear that I do not have more info as I already posted. If you look at my mount script (what I posted above), you see that it creates a log file.
I cleared the old one to definitively get the exact beginning of it. So I re-copied from this file and this is what I get:
2020/12/16 11:13:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:14:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:15:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:16:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:17:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:18:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:19:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:20:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:21:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:22:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:23:47 INFO : Cleaned the cache: objects 7 (was 7), total size 97.790G (was 97.790G)
2020/12/16 11:24:32 DEBUG : rclone: Version "v1.48.0" starting with parameters ["/usr/bin/rclone" "mount" "--log-file" "/home/plexuser/logs/plexmedia_rclone.log" "--log-level" "DEBUG" "--umask" "002" "--allow-other" "--dir-cache-time=160h" "--drive-chunk-size=512M" "--vfs-cache-max-age=72h" "--vfs-cache-mode" "full" "--cache-dir" "/home/plexuser/uploads" "--config" "/path_to/rclone.conf" "PlexMedia_crypt:" "/media/PlexMedia_crypt"]
2020/12/16 11:24:32 DEBUG : Using config file from "/path_to/rclone.conf"
After that this API thing starts.
Is there anything else what I might forgot?

THIS IS VERY interesting and I didn't notice until your hint. Before I added/changed this --vfs-cache-mode full option, the disk space usage was < 3%
Accordingly, you should be right! This cash is there.
However, will it be deleted?
One more interesting thing: Since we talked some hours ago something happened in the meantime... This log file got incredible long and looking in it there are some movies listed I definitively did not touch in the meantime. Is this because of Plex scanning procedures?
And it is still doing something (it's getting longer and longer!).

Do you have any idea how to fix it?

THANK YOU

Animosity022 · December 16, 2020, 1:02pm

That's the wrong version to use vfs-cache-mode full and not the version you posted above. You need to update rclone.

In this post, you had noted you have the latest, but the debug log shows an ancient version.

That's why we ask for the full debug log so we don't go back and forth and waste time.

I don't have any visibility into your network/setup so I can't offer much unfortunately. You'd want to talk to your system/network admin and figure out what's going on with that as not being able to resolve DNS is not a normal thing.

Engelbrecht · December 16, 2020, 1:05pm

Strange.
I certainly did rclone version. See
plexuser@Server_name:~$ rclone version

rclone v1.53.3

os/arch: linux/amd64
go version: go1.15.5

Animosity022 · December 16, 2020, 1:06pm

Where ever you are running it from does not match as seen in your debug log.

Engelbrecht · December 16, 2020, 1:08pm

I got it. But I do not get the discrepancy.

Animosity022 · December 16, 2020, 1:21pm

You'd want to check your paths and see if you have another version

felix@gemini:/var/log$ which rclone
/bin/rclone
felix@gemini:/var/log$ /bin/rclone --version
rclone v1.53.3
- os/arch: linux/amd64
- go version: go1.15.5

Engelbrecht · December 16, 2020, 1:50pm

Okay. I did the following

plexuser@Server_name:~$ curl https://rclone.org/install.sh | sudo bash

The latest version of rclone rclone v1.53.3 is already installed.

This was what I did when I installed rclone the first time

Animosity022 · December 16, 2020, 1:52pm

You'd want to check the actual binary you are using.

felix@gemini:/var/log$ which rclone
/bin/rclone
felix@gemini:/var/log$ /bin/rclone --version
rclone v1.53.3
- os/arch: linux/amd64
- go version: go1.15.5

and check your service file to see what that points to.

Engelbrecht · December 16, 2020, 2:06pm

Sorry, but I dont get it.
could you please explain what do you mean and how to put in the commands, in detail?
Please apologize, but there is neither a folder "rclone" in "/bin" nor in /var/logs

Animosity022 · December 16, 2020, 2:07pm

Type:

which rclone

Share the output.

Engelbrecht · December 16, 2020, 2:08pm

plexuser@Servr_name:/bin$ which rclone

/usr/sbin/rclone

Animosity022 · December 16, 2020, 2:12pm

So the rclone install script does not install into /usr/sbin which is a strange spot for it. It seems like someone installed there for whatever reason manually.

If you run:

/usr/bin/rclone --version
/usr/sbin/rclone --version

and share the output of both of those commands.

Engelbrecht · December 16, 2020, 2:17pm

rclone v1.48.0

os/arch: linux/amd64
go version: go1.12.6

and

rclone v1.53.3

os/arch: linux/amd64
go version: go1.15.5

okay... I see what you mean. However, what can i do?

Sudden buffering when streaming high bitrate 4k content on Plex

What is the problem you are having with rclone?

What is your rclone version (output from rclone version)

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Which cloud storage system are you using? (eg Google Drive)

The command you were trying to run (eg rclone copy /tmp remote:tmp)

The rclone config contents with secrets removed.

What is your rclone version (output from `rclone version`)

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)