rclone crashing when plex library scan happens, but doesnt when i enable rclone log file.

[drpau]

What is your rclone version (eg output from rclone -V)

ash-4.3# ./rclone --version
rclone v1.39-184-gb91bd324-vfs-updateβ
- os/arch: linux/amd64
- go version: go1.10

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

ash-4.3# uname -a
Linux Syn 3.10.102 #15254 SMP Fri Jan 26 06:46:44 CST 2018 x86_64 GNU/Linux synology_braswell_916+

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

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

/volume1/rclone1.39-184/rclone mount this_one: /mnt/gdrive.de/ --allow-other --config=/volume1/rclone.conf --log-file=/dev/null &

I am running the above command and this is appearing to artificially slow down the library scan. (eg what normally takes approx 20mins, now takes a few hours).

If i remove --logfile=/dev/nulll the speed increase returns however rclone regularly crashes. I have tried to log the output to capture the crash, however, when logging is enabled this seemingly artificial slowdown improves stability.

I have rclone same config / same setup on multiple boxes and it appears to be only affecting my Synology NAS (DS916+ 8GB).

It appears that the amount of requests that are done with a Scan of Library in PMS, causes rclone to crash if its not being forced to write a log file. With the log file enabled, it is far slower, but far more stable.

Not sure how to proceed as any attempts at verbosity/logging, assists stability... but to repeat the error i need to disable logging and verbosity :(

[ncw]

You could try this instead

rclone mount this_one: /mnt/gdrive.de/ --allow-other --config=/volume1/rclone.conf >/tmp/rclone.log 2>&1 &

I'm suprised --log-file /dev/null makes such a difference

rclone v1.39-184-gb91bd324-vfs-updateβ

can you try the latest beta also as I just fixed a potential crash

[remusb]

rclone talks with Plex during reading only. Unless you were also reading a file at the same time with the scan, there would be no talking between the two. I've just verified this to be sure.

Just to be sure, can you try without the Plex configuration and see if that helps?

[danielloader]

Quick question, is this polled or websocket pushed? Wondering how long it takes the mount to notice it's trying to playback media before triggering more workers.

[drpau]

I have grabbed 1.39-195 and am running that now.
rather than doing this command
rclone mount this_one: /mnt/gdrive.de/ --allow-other --config=/volume1/rclone.conf >/tmp/rclone.log 2>&1 &
i ran this instead (just to be sure --cache-db-purge):
./rclone mount this_one: /mnt/gdrive.de/ --allow-other --config=/volume1/rclone.conf --cache-db-purge >/tmp/rclone.log 2>&1

I have manually kicked off a scan and it is performing at the same speed as expected when writing output/logging. So its not as quick as when doing no logging.

this is the result of the log file (tmp/rclone.log)

ash-4.3# cat /tmp/rclone.log
2018/03/02 10:01:32 INFO  : cache: Cache DB path: /root/.cache/rclone/cache-backend/cache.db
2018/03/02 10:01:32 INFO  : cache: Cache chunk path: /root/.cache/rclone/cache-backend/cache
2018/03/02 10:01:34 INFO  : cache: Chunk Memory: true
2018/03/02 10:01:34 INFO  : cache: Chunk Size: 5M
2018/03/02 10:01:34 INFO  : cache: Chunk Total Size: 500M
2018/03/02 10:01:34 INFO  : cache: Chunk Clean Interval: 1m0s
2018/03/02 10:01:34 INFO  : cache: Workers: 4
2018/03/02 10:01:34 INFO  : cache: File Age: 3h0m0s
2018/03/02 10:01:34 INFO  : cache: Cache DB path: /root/.cache/rclone/cache-backend/cache.db
2018/03/02 10:01:34 INFO  : cache: Cache chunk path: /root/.cache/rclone/cache-backend/cache
2018/03/02 10:01:34 INFO  : cache: Chunk Memory: true
2018/03/02 10:01:34 INFO  : cache: Chunk Size: 5M
2018/03/02 10:01:34 INFO  : cache: Chunk Total Size: 500M
2018/03/02 10:01:34 INFO  : cache: Chunk Clean Interval: 1m0s
2018/03/02 10:01:34 INFO  : cache: Workers: 4
2018/03/02 10:01:34 INFO  : cache: File Age: 3h0m0s
2018/03/02 10:01:34 INFO  : Encrypted drive 'this_one:': Modify window is 1ms
ash-4.3#

my next step is to remove plex integration to the cache remote and test.

[drpau]

Just to be sure, can you try without the Plex configuration and see if that helps?

i have just removed the plex integration from the cache remote config, and it is blazingly fast.

[remusb]

@Daniel-Loader polled. Typically after the first few chunks are read it will pick up in rclone too. It's actually Plex that takes longer to say that it's playing something. This is especially worse if it's transcoding, the transcoder will need more data before actually saying it's playing something.

rclone checks this at every new chunk which is a suitable compromise I would say. Once it's confirmed, it doesn't check again the entire playback.

[remusb]

@drpau It's a bit weird that none of your commands have any verbosity preference yet it's clear that logs are written out (console or file).

Here's what should happen with -v which seems to be the same level as yours:

bunduc-osx:rclone bunduc$ ./rclone mount -v --allow-other test_crypt: /Users/bunduc/Downloads/gdrive.de/ --cache-tmp-wait-time=5m
2018/03/02 10:37:20 INFO  : test_cache: Cache DB path: /Users/bunduc/Library/Caches/rclone/cache-backend/test_cache.db
2018/03/02 10:37:20 INFO  : test_cache: Cache chunk path: /Users/bunduc/Library/Caches/rclone/cache-backend/test_cache
2018/03/02 10:37:20 INFO  : test_cache: Chunk Memory: true
2018/03/02 10:37:20 INFO  : test_cache: Chunk Size: 5M
2018/03/02 10:37:20 INFO  : test_cache: Chunk Total Size: 10G
2018/03/02 10:37:20 INFO  : test_cache: Chunk Clean Interval: 1m0s
2018/03/02 10:37:20 INFO  : test_cache: Workers: 4
2018/03/02 10:37:20 INFO  : test_cache: File Age: 24h0m0s
2018/03/02 10:37:20 INFO  : test_cache: Cache DB path: /Users/bunduc/Library/Caches/rclone/cache-backend/test_cache.db
2018/03/02 10:37:20 INFO  : test_cache: Cache chunk path: /Users/bunduc/Library/Caches/rclone/cache-backend/test_cache
2018/03/02 10:37:20 INFO  : test_cache: Chunk Memory: true
2018/03/02 10:37:20 INFO  : test_cache: Chunk Size: 5M
2018/03/02 10:37:20 INFO  : test_cache: Chunk Total Size: 10G
2018/03/02 10:37:20 INFO  : test_cache: Chunk Clean Interval: 1m0s
2018/03/02 10:37:20 INFO  : test_cache: Workers: 4
2018/03/02 10:37:20 INFO  : test_cache: File Age: 24h0m0s
2018/03/02 10:37:20 INFO  : Encrypted drive 'test_crypt:': Modify window is 1ms
^C
2018/03/02 10:37:25 INFO  : Signal received: interrupt
2018/03/02 10:37:25 INFO  : Exiting...

Versus what your actual commands should output:

bunduc-osx:rclone bunduc$ ./rclone mount --allow-other test_crypt: /Users/bunduc/Downloads/gdrive.de/ --cache-tmp-wait-time=5m
^C
bunduc-osx:rclone bunduc$

This wouldn't be an issue really except that the symptoms you mention seem related to logging and this is a weird aspect of it.

[remusb]

Someone reported something similar in the forums and posted some logs that hinted at a spammy log level from Plex.

@drpau try this version please: https://beta.rclone.org/v1.39-259-g4924ac2f/

[danielloader]

Any chance this will have a linux x64 build too?

[drpau]

@remusb thanks - will do but like @Daniel-Loader i need this as linuxamd64 build on my synology.

[remusb]

@drpau yes, it got uploaded in the meantime

[danielloader]

Can confirm that plex entries aren't filling the log, systemd was working overtime log rotating before!

[remusb]

As mentioned in the forum, this does indicate that something changed on Plex's side to respond with an unexpected format. Likely a newer version that changed the API response.

I can't replicate on my end even if I already have the latest version so it will help to know what Plex versions are you guys running that were facing this (and the OS).

[danielloader]

Sure, I was running v210 prior to v259, plex version 1.12.1.4871. Since I've noticed plex has an update out (Version 1.12.1.4885) I'll go download it.

[remusb]

Ok. I'm doing an Version 1.12.0.4829 You must have the Premium Pass or something.

It sounds like Plex changed the API. Now I'm dissapointed in them cause they're not keeping it backwards compatible. I don't like playing the cat and mouse with this. Perhaps we need a different way to handle this playback sync. I'll do some research and thinking.

In the meantime, can you confirm if the Plex playback sync still works? You should see a log like confirmed reading with -v

[danielloader]

Can confirm I have plexpass and the associated updates.

Here's a gist of the debug level logs: https://gist.githubusercontent.com/daniel-loader/c9943672224b490e6021b52089b4d4ac/raw/8ad4b1f960b91cb34b4481a629ceca21d7866fd2/gistfile1.txt

I mounted the remote, started plex, played a single video (though it took 45 seconds to start playback) and stopped it after a minute or two.

I suspect by the performance, it isn't working.

[remusb]

2 options at this point cause I also don't see the file names in the plex logs:

• disable the Plex integration from rclone (scans will be more hungry and prefetch more data - but shouldn't really cause 503s)
• roll back to an earlier version of Plex

I'll have to research this a bit and see if the Plex API is still able to tell us what actual file on disk is playing. Problem to that is that I also don't have the build but I might have a way to get it.

[danielloader]

I've rolled back to public builds of Plex in the meantime.

[remusb]

There seems to be a feature for Plex webhooks but it's only available for Plex Pass. While I wouldn't mind paying the bill for Plex (long time user, they deserve the support), that would still bind this feature to a paid one which I don't want to do.

I'll try to get the updated build next week and try to port the API usage to the new version. I'm still keeping my eyes open for alternative ways of doing this. Any suggestions are welcome

[danielloader]

Yeah while I totally agree that there shouldn't be a requirement to have a plexpass for use, the difference between webhooks and API polling can be felt with Tautulli, having tried both methods - as one expects, webhooks are much better for detecting playback.

Edit: for clarification - plexpy had the option of either websockets or polling, as of plexpy 2 (renamed tautulli) it's websocket only. Are websockets plexpass only then? If so it seems weird tautulli only works with plexpass installs.

[remusb]

@Daniel-Loader thanks for that. I can see the notifications on my Plex Server using WS so it seems to be public.

I'll do some testing with it.

[remusb]

so this made it in the latest beta: https://beta.rclone.org/v1.40-012-g0ed0d9a7/ (it will be a few mins more to populate the others)

It's using @Daniel-Loader 's suggestion with websockets and I managed to update to the troubled version to confirm it works with it too.

[seuffert]

@remusb do i read your code correctly and the websocket connection does not reconnect if it fails (e.g. plex server restart) ?

[danielloader]

Just restarted plex 3 times via systemd and initiated a playback each time, seems to be picked up in the rclone logs as a new playback.

edit: Pleased to say it works on plexpass builds as expected, know you tested it but external verification and all that.

[seuffert]

right - websockets take care of reconnecting.

@remusb one more question, any reason in particular you chose golang.org/x/net/websocket over github.com/gorilla/websocket? just curious :)

[remusb]

@seuffert I found a table somewhere comparing both versions, x/net/websocket was already in the project, had enough features for this simple use case so I went with it.

[remusb]

Sounds like this is good so I'm closing the ticket