Rclone Mount Access Stops Occasionally. Pulling My Hair Out

ok, will do. I will replicate the issue and time stamp..

really appreciate your help.

do you just require movies.service debug logs ? what else would help you ?

I would think just whatever mount you are having issues with is fine as that should be a good starting point.

ok, just happened again

failed at 22:35:12.
Plex was spinning without activity until 22:39:00.

And service after reboot at 22:20

plex@plex:~$ journalctl -u movies --since '25 minutes ago'
-- Logs begin at Tue 2020-04-14 11:41:16 AEST, end at Mon 2020-05-18 22:44:09 AEST. --
May 18 22:20:20 plex systemd[828]: movies.service: Executing: /usr/bin/rclone mount '--user-agent=Movies/Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36' --config=/home/plex/.config/rclone
May 18 22:20:20 plex systemd[1]: Started Google Movies Drive (rclone).

And systemctl status

plex@plex:~$ systemctl status movies
● movies.service - Google Movies Drive (rclone)
Loaded: loaded (/etc/systemd/system/movies.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2020-05-18 22:20:20 AEST; 25min ago
Main PID: 828 (rclone)
Tasks: 20 (limit: 4915)
CGroup: /system.slice/movies.service
└─828 /usr/bin/rclone mount --user-agent=Movies/Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36 --config=/home/plex/.config/rclone/rclone.conf --log-file=/logs/rcmovies.txt --lo

May 18 22:20:20 plex systemd[1]: Started Google Movies Drive (rclone).

So the server was rebooted at 20:18 and just came back online?

At 20:20, you had some DNS issues as well:

2020/05/18 22:20:20 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/05/18 22:20:20 DEBUG : pacer: Rate limited, increasing sleep to 1.48283365s
2020/05/18 22:20:20 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/05/18 22:20:20 DEBUG : pacer: Rate limited, increasing sleep to 2.619902817s
2020/05/18 22:20:22 DEBUG : pacer: low level retry 3/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)
2020/05/18 22:20:22 DEBUG : pacer: Rate limited, increasing sleep to 4.190409763s
2020/05/18 22:20:24 DEBUG : pacer: low level retry 4/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&prettyPrint=false&supportsAllDrives=true: dial tcp: lookup www.googleapis.com on 127.0.0.53:53: server misbehaving)

What are the errors in the plex logs as it doesn't seem like it is hitting the mount at all during that time period.

Yes, rebooted at 22:20

Here is the Plex Media Server.log

https://drive.google.com/open?id=1acf2TFR5vVEkKCzyMrqUC7Vu8npmn1_R

Can you link to something that I don't have to request access to?

sorry

https://drive.google.com/open?id=1acf2TFR5vVEkKCzyMrqUC7Vu8npmn1_R

The Plex logs look like it is grabbing metatadata about whatever you were playing.

You can see in the plex logs starting at time:

ers%2Fcom%2Eplexapp%2Eagents%2Ethemoviedb_e49a93271e05ed7d3a2df7a3dba068aef4947281
May 18, 2020 22:26:35.028 [0x7f01867fc700] DEBUG - Calculated media file path for path [metadata://posters/com.plexapp.agents.themoviedb_e49a93271e05ed7d3a2df7a3dba068aef4947281]: ["/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Metadata/Movies/e/085e1a25f8aa8bb290a3b2aba7a98bf7ce3025f.bundle/Contents/_combined/posters/com.plexapp.agents.themoviedb_e49a93271e05ed7d3a2df7a3dba068aef4947281"]
May 18, 2020 22:26:35.029 [0x7f01867fc700] DEBUG - Calling back into ourselves for photo to transcode, optimizing the process (status: -1)
May 18, 2020 22:26:35.029 [0x7f01867fc700] DEBUG - Photo cache obtained 688096 bytes from /library/metadata/3156/thumb/1589731551?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
May 18, 2020 22:26:35.029 [0x7f01867fc700] DEBUG - Saving original media file to /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/PhotoTranscoder/5e/5e6325b738f4d247a3d81cf51fa73984d36d9509.jpg
May 18, 2020 22:26:35.033 [0x7f01877fe700] DEBUG - Auth: authenticated user 1 as boggy
May 18, 2020 22:26:35.034 [0x7f012dffb700] DEBUG - Request: [192.168.1.206:50006 (Subnet)] GET /photo/:/transcode?width=156&height=234&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F3326%2Fthumb%2F1589731558%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxx (18 live) TLS GZIP Signed-in Token (boggy)
May 18, 2020 22:26:35.034 [0x7f012dffb700] DEBUG - Photo transcoder: Request for url [/library/metadata/3326/thumb/1589731558?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx] (is local: 1 upscaled: 1)
May 18, 2020 22:26:35.035 [0x7f012dffb700] DEBUG - Auth: authenticated user 1 as boggy
May 18, 2020 22:26:35.036 [0x7f012dffb700] DEBUG - Computed media url for item 3326: http://127.0.0.1:43149/system/agents/media/get?guid=com%2Eplexapp%2Eagents%2Ethemoviedb%3A%2F%2F300693%3Flang%3Den&mediaType=1&url=metadata%3A%2F%2Fposters%2Fcom%2Eplexapp%2Eagents%2Ethemoviedb_28d84d4b6101bfe79cfa58513e95f9ecffa68c77
May 18, 2020 22:26:35.036 [0x7f012dffb700] DEBUG - HTTP requesting GET http://127.0.0.1:43149/system/agents/media/get?guid=com%2Eplexapp%2Eagents%2Ethemoviedb%3A%2F%2F300693%3Flang%3Den&mediaType=1&url=metadata%3A%2F%2Fposters%2Fcom%2Eplexapp%2Eagents%2Ethemoviedb_28d84d4b6101bfe79cfa58513e95f9ecffa68c77
May 18, 2020 22:26:35.040 [0x7f012dffb700] DEBUG - HTTP 200 response from GET http://127.0.0.1:43149/system/agents/media/get?guid=com%2Eplexapp%2Eagents%2Ethemoviedb%3A%2F%2F300693%3Flang%3Den&mediaType=1&url=metadata%3A%2F%2Fposters%2Fcom%2Eplexapp%2Eagents%2Ethemoviedb_28d84d4b6101bfe79cfa58513e95f9ecffa68c77
May 18, 2020 22:26:35.040 [0x7f012dffb700] DEBUG - Calculated media file path for path [metadata://posters/com.plexapp.agents.themoviedb_28d84d4b6101bfe79cfa58513e95f9ecffa68c77]: ["/var/lib/plexmediaserver/Library/Application Sup

So I'd expect no mount access yet as it's just grabbing metadata which takes a godawful time as it doesn't start the stream request until much later:

May 18, 2020 22:26:39.136 [0x7f012dffb700] DEBUG - Created thumbnail of size 156x234, has pixels: 1
May 18, 2020 22:26:39.139 [0x7f01877fe700] DEBUG - Completed: [192.168.1.206:50004] 200 GET /photo/:/transcode?width=156&height=234&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F1593%2Fthumb%2F1589785572%3FX-Plex-Token%3Dxxxxxxx
xxxxxxxxxxxxx (18 live) TLS GZIP 44ms 11421 bytes (pipelined: 19)
May 18, 2020 22:26:42.974 [0x7f00e77fe700] DEBUG - Last refresh (2020-05-18 22:10:30) appears to be older than directory change time (2020-05-18 22:20:20), need to refresh local media agent.
May 18, 2020 22:26:42.975 [0x7f01567fc700] DEBUG - Streaming Resource: Attempting to create AdHoc dp session 5ppj3eizzf0lh0plp5dfeqm2 for part 2893
May 18, 2020 22:26:42.976 [0x7f00e77fe700] DEBUG - Refreshing GUID: 'com.plexapp.agents.themoviedb://429416?lang=en'

as it starts to play around here:

May 18, 2020 22:26:42.978 [0x7f01567fc700] DEBUG - TranscodeUniversalRequest: using profile Generic

The time spinning is all inside Plex updating metadata for the movie being played from the logs.

As for the plex logs, I also check out another mount whilst it was down to ensure I wasn't losing it and I could actually watch other streams on other mounts.. Hence the activity. I will NOT do this next time so the plex logs will be better informed.

Oh, yeah, that would make it a bit tough to see what's going on if other things are happening.

You definitely have an interesting situation so far though!

yeah, its killing me.. I can go all day and night running a movie one after the other, and it doesn't miss a beat. Internet is pretty good most of the time.. As soon as you leave it for a small period of time, it almost resets the connection. I thought is was Google API, so created seperate mounts.. Google API activity is very low. No scanning, no other data usage. bandwidth use is minimal..

I will do some more logging on the plex side to see if I can see anything.

Thanks again for your help. really appreciate it.. have invested so much time trying to get an answer as to why. even happens on multiple servers, ubuntu 16, 18.. about to rebuild again to test on another..

Thanks Animosity for your help.. I am pretty sure now it is an internet issue of sorts.. Almost like Plex is queuing the process before going further, and Rclone is always live and waiting for the request to play. SO it would appear Rclone Mount is stable, yet PLEX server is not processing the request untill it can connect to TMDB or similar for thumbnails etc.

I have turned off Google Drive Stream from my Computer, I have changed DNS on the Ubuntu PLEX Server, and even changed Routers, the issue seems better, but appears to be Internet related.

I could only replace my Unifi Router with Another Unifi router, so doesn't really remove that as the fault. I have seen other chats where users have issues with USG Unifi and Plex..

Next Step is to change Routers for something completely different and see how it goes.

I have learnt so much in this process, and now knowing what is going on I can at least know why the lag is there...

Will certainly update should I find further info..

Ciao

1 Like

That is progress so good news although I am sure it's frustrating!

If it something Plex, you could always post up on the Plex forums as well and include all the logs. There are helpful as well and very good at diagnosing things like that as well as I've found Plex bugs before too!

Almost sounds router/net related.

Not sure if it can be related, but you can try the latest beta, it has this fix : https://github.com/rclone/rclone/commit/3de9bd9d0411ab9ba78f6072c12a5a89fbeea2e7

Again I'm not sure it's that, but...

I get the same error with v1.51.0. The problem was not there with earlier versions that I have had running (I cannot remember exact versions).

The rclone mount command just exists suddenly, usually within a day.

There is no signs of why in the logs, nothing looks different from when I stop it intentionally. Just the same "rclone finishing / cache cleaner exiting" message.

I see this only on Synology, for some reason. No problems on CentOS or Ubuntu.

bash-4.3# uname -a
Linux synology 3.10.105 #24922 SMP Wed Jul 3 16:35:54 CST 2019 x86_64 GNU/Linux synology_bromolow_3615xs
bash-4.3# /bin/rclone --version
rclone v1.51.0
- os/arch: linux/amd64
- go version: go1.13.7
bash-4.3#

That's not the same error as the OP has the process still running. If you mount is exiting, that's something different. If it exits, that would be a message on the debug logs as that's not normal or something else is stopping it.

Ah, thanks.

The service wrapping and "Restart=on-failure" lead me astray.

Yes, that's what I would expect. And I am unable to fathom what it would be that would be stopping it.