@remus.bunduc is “SIGHUP” supported by your CACHE to flush all directory caches? like it was before with the mount command (https://github.com/ncw/rclone/pull/1376)
@remus.bunduc are plex username and plex password the credentials used for plex.tv or the local system user running the plex-processes?
ok so I got a logfile where I can’t see anything special, but half of the movies disappeared from the plex library again. The log is big, so I don’t want to put it into this thread. On the local mount the files of the disappeared movies are gone, only the folders and subfolders remain.
rclone: Version “v1.38-223-g7c972d37β” starting with parameters ["/usr/local/bin/rclone-beta" “mount” “-vv” “plexdrive:/” “/mnt/.plexd” “–allow-other” “–config=/home/dellinger/.config/rclone/rclone.conf”]
but no entries in the logfile like “unexpected conditions during reading. current position…”
@remus.bunduc - Thanks for your reply and investigation. This is my Rclone config (sanitized):
[Google]
type = drive
client_id =
client_secret =
token = {"access_token":"ya------------Yk","token_type":"Bearer","refresh_token":"1/xxxxxxxx","expiry":"2017-12-10T07:25:03.56635514-07:00"}
[GoogleCache]
type = cache
remote = Google:
chunk_size = 5M
info_age = 5m
chunk_age = 3h
warmup_age = 24h
plex_url = http://127.0.0.1:32400
plex_username = Ken@-----.com
plex_password = DSa-----------V
plex_token = ------------
And, I’m starting Rclone-mount via:
/usr/sbin/rclone mount \
--allow-other \
--log-file /home/kelinger/logs/rclone.log \
--config /home/kelinger/.config/rclone/rclone.conf \
--log-level INFO \
--cache-db-purge \
GoogleCache:/ /home/kelinger/rcloneAlso, if it helps, during the scan itself, I see some errors like below. However, even if I’m not even running Plex, I still have files disappearing after some short time so this may not be a true indicator:
2017/12/10 11:22:58 ERROR : /Plex/TV Shows/Dirk Gently's Holistic Detective Agency/Season 02/Dirk Gently's Holistic Detective Agency - S02E09 - Trouble is Bad.mkv: unexpected conditions during reading. current position: 2222018560, current chunk position: 2217738240, current chunk size: 2314240, offset: 4280320, chunk size: 5242880, file size: 2222087230
2017/12/10 11:22:58 ERROR : /Plex/TV Shows/Dirk Gently's Holistic Detective Agency/Season 02/Dirk Gently's Holistic Detective Agency - S02E09 - Trouble is Bad.mkv: (2222018560/2222087230) error (unexpected EOF) response
2017/12/10 11:22:58 ERROR : Plex/TV Shows/Dirk Gently's Holistic Detective Agency/Season 02/Dirk Gently's Holistic Detective Agency - S02E09 - Trouble is Bad.mkv: ReadFileHandle.Read error: low level retry 1/10: EOFGot some Errors now too, but I guess this has nothing to do with the disappearing files, cause half of my 120 movies in the library are gone again.
2017/12/10 17:47:27 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/o5g4aa3oqqjicrnlnlp911ggq0/9l831tbu5jqrg9vkt072h7iil4/ifm1cu79pmpkpjoeb7uhq1b2140pqhi0eaknnlbjd3eg184j7il3keefukdqg2cn88rbhfvp5m9vlejs4do0fscvgtpi09khptc7voo/dluu60rk84o66o76htmuekac3jv9bmdct58lea875hrl24hrig2g: unexpected conditions during reading. current position: 1906973264, current chunk position: 1897922560, current chunk size: 4235264, offset: 9050704, chunk size: 10485760, file size: 1907053588
2017/12/10 17:47:27 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/o5g4aa3oqqjicrnlnlp911ggq0/9l831tbu5jqrg9vkt072h7iil4/ifm1cu79pmpkpjoeb7uhq1b2140pqhi0eaknnlbjd3eg184j7il3keefukdqg2cn88rbhfvp5m9vlejs4do0fscvgtpi09khptc7voo/dluu60rk84o66o76htmuekac3jv9bmdct58lea875hrl24hrig2g: (1906973264/1907053588) error (unexpected EOF) response
2017/12/10 17:47:27 ERROR : Serien/Colony/Season 2/Colony.S02E02.German.Dubbed.DL.1080p.WebHD.x264-ARC/arc-colony.s02e02.1080p.mkv: ReadFileHandle.Read error: low level retry 1/10: EOF
2017/12/10 17:53:23 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/o5g4aa3oqqjicrnlnlp911ggq0/dtsrq3fqcrbv6mg3du3m4f70ik/0ophpbo6ts0g4f3v7iinp530734dqtstr8rj6tlq9o584ddf9qla141m50fv35o52qqb37b38nuhj3b53q0918rtc86nrap8g4o1sso/utdk2jfsdibhahdhqctn9sirq2dm59oqlbakil30ib1g5jq23big: (1891240784/3486612671) error (chunk not found 1887436800) response
2017/12/10 17:53:23 ERROR : Serien/Colony/Season 1/Colony.S01E03.German.Dubbed.DL.1080p.WebHD.x264-ARC/arc-colony.s01e03.1080p.mkv: ReadFileHandle.Read error: low level retry 1/10: EOF
2017/12/10 17:54:34 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/uk9ujkho978lv1eurgtu5lc07g/31e17ljbr5ktp06d8idvi6an9g/sdfga4v0dun16f3odu0vc22uk9fh6hmc8bhg20kc9fvga7datdm5o02sfa8eag1noqmvves6jnk8aj7jodc9gg5spv06cssv3so7rb0qfknv84nfahacter9ui9c82d5j48c31prnhsa0dhdohof24b50eo0ur1cvgjmlqomqjko6tvbkp51ofgp0l3da6efnivjuh7iu01bk: unexpected conditions during reading. current position: 3058328592, current chunk position: 3051356160, current chunk size: 2527232, offset: 6972432, chunk size: 10485760, file size: 6041306955
2017/12/10 17:54:34 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/uk9ujkho978lv1eurgtu5lc07g/31e17ljbr5ktp06d8idvi6an9g/sdfga4v0dun16f3odu0vc22uk9fh6hmc8bhg20kc9fvga7datdm5o02sfa8eag1noqmvves6jnk8aj7jodc9gg5spv06cssv3so7rb0qfknv84nfahacter9ui9c82d5j48c31prnhsa0dhdohof24b50eo0ur1cvgjmlqomqjko6tvbkp51ofgp0l3da6efnivjuh7iu01bk: (3058328592/6041306955) error (unexpected EOF) response
2017/12/10 17:54:47 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/uk9ujkho978lv1eurgtu5lc07g/31e17ljbr5ktp06d8idvi6an9g/o00jl2olkqqap5j0v6ooua9u8dhkf3qdd94d4mdp5vqqjs7s91qkfgne9lmlq9avkfki80lcv9ribispa7rk8f953jbaf7pn1a9j4vd0heu53gbnmg0o79p91bovpgug218ea3ma1im9umdggpj2kg61hg: unexpected conditions during reading. current position: 1905465568, current chunk position: 1897922560, current chunk size: 5267456, offset: 7543008, chunk size: 10485760, file size: 3647498012
2017/12/10 17:54:47 ERROR : /gdroplet/1fik3a1v55nlsh5b97ooipcvec/b27edi5725me2n5ejiejo04kd4/uk9ujkho978lv1eurgtu5lc07g/31e17ljbr5ktp06d8idvi6an9g/o00jl2olkqqap5j0v6ooua9u8dhkf3qdd94d4mdp5vqqjs7s91qkfgne9lmlq9avkfki80lcv9ribispa7rk8f953jbaf7pn1a9j4vd0heu53gbnmg0o79p91bovpgug218ea3ma1im9umdggpj2kg61hg: (1905465568/3647498012) error (unexpected EOF) responseYes, mine are still disappearing with the latest beta as well. However, I’m actually nearly complete doing my TV Show scan so I’m able to get a lot further.
I don’t think the panic is related to the the files going away from cache.
The previous beta seems to confirm that the panic is gone though it does show that some few kb get lost from the end of the file for reasons unknown yet. I’m experimenting a fix for it. More details here and the latest beta with the experimental fix: https://github.com/ncw/rclone/issues/1896
@seuffert SIGHUP should be easy to add. I have a lot on my plate right now, would you be so kind to open a feature request so I won’t forget about it?
@Shacuih plex username and password are the ones you login on plex.tv.
I’m going to start looking in the disappearances. I could use a bit of details:
- don’t they appear on a
lsor any other activity of the sort? - what OS does this happen on?
- is it consistent with the
cache-info-age? As in: do they go away from cache after that time?
@remus.bunduc - does this help?
I’m using Ubuntu 16.04.3 LTS (GNU/Linux 4.4.0-103-generic x86_64) with the latest updates and rclone v1.38-224-g829dd1adβ. Here are the results of multiple LS commands (identical results have been eliminated to minimize the size of this message but I checked every 3-4 minutes). At first, while I’m copying a file, the rest of the files disappeared. Then, 5-10 minutes later, the file I was copying also disappeared:
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ date
Sun Dec 10 17:19:35 MST 2017
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/ 10 Cloverfield Lane (2016).eng.srt 10 Cloverfield Lane (2016).mkv clearart.png disc.png fanart.jpg folder.jpg imdb.url logo.png movie.nfo poster.jpg tmdb.url
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ time cp 10\ Cloverfield\ Lane\ \(2016\).mkv /tmp
real 5m54.589s
user 0m0.036s
sys 0m6.120s
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/ 10 Cloverfield Lane (2016).mkv
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ date
Sun Dec 10 17:27:17 MST 2017
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/ 10 Cloverfield Lane (2016).mkv
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/ 10 Cloverfield Lane (2016).mkv
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ date
Sun Dec 10 17:28:42 MST 2017
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/ 10 Cloverfield Lane (2016).mkv
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ date
Sun Dec 10 17:30:58 MST 2017
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ ls
extrafanart/
┌─[kelinger@Hecubus]─[~/rclone/Plex/Movies/10 Cloverfield Lane (2016)]
└──╼ date
Sun Dec 10 17:37:05 MST 2017
Meanwhile, the logs show this:
2017/12/10 17:25:17 INFO : cache: deleted (0) chunks
2017/12/10 17:25:33 INFO : cache: deleted (577) entries
2017/12/10 17:30:55 INFO : cache: deleted (0) chunks
2017/12/10 17:30:55 INFO : cache: deleted (1) entries
2017/12/10 17:36:52 INFO : cache: deleted (0) chunks
2017/12/10 17:36:52 INFO : cache: deleted (6) entries@remus.bunduc Thanks for your efforts on investigating the disappearance problem.
I hope this helps a little bit.
OS:
uname -a Linux hyperion 4.10.0-40-generic #44~16.04.1-Ubuntu SMP Thu Nov 9 15:37:44 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
2017/12/11 13:00:19 INFO : plexcache: Storage DB path: /home/dellinger/.cache/rclone/cache-backend/plexcache.db
2017/12/11 13:00:20 INFO : plexcache: Chunk Memory: true
2017/12/11 13:00:20 INFO : plexcache: Chunk Size: 10M
2017/12/11 13:00:20 INFO : plexcache: Chunk Total Size: 1000G
2017/12/11 13:00:20 INFO : plexcache: Chunk Clean Interval: 1m0s
2017/12/11 13:00:20 INFO : plexcache: Workers: 4
2017/12/11 13:00:20 INFO : plexcache: File Age: 1h0m0s
2017/12/11 13:00:20 INFO : plexcache: Cache Writes: false
2017/12/11 13:00:20 INFO : cache: deleted (0) chunks
2017/12/11 13:00:20 INFO : cache: deleted (0) entries
2017/12/11 13:00:20 INFO : plexcache: Storage DB path: /home/dellinger/.cache/rclone/cache-backend/plexcache.db
2017/12/11 13:00:20 INFO : plexcache: Chunk Memory: true
2017/12/11 13:00:20 INFO : plexcache: Chunk Size: 10M
2017/12/11 13:00:20 INFO : plexcache: Chunk Total Size: 1000G
2017/12/11 13:00:20 INFO : plexcache: Chunk Clean Interval: 1m0s
2017/12/11 13:00:20 INFO : plexcache: Workers: 4
2017/12/11 13:00:20 INFO : plexcache: File Age: 1h0m0s
2017/12/11 13:00:20 INFO : plexcache: Cache Writes: false
2017/12/11 13:00:20 INFO : Encrypted drive 'plexdrive:/': Modify window is 1ms
2017/12/11 13:00:20 INFO : cache: deleted (0) chunks
2017/12/11 13:00:21 NOTICE: Encrypted drive 'plexdrive:/': poll-interval is not supported by this remote
2017/12/11 13:00:21 INFO : cache: deleted (0) entries
2017/12/11 13:01:34 INFO : cache: deleted (0) chunks
2017/12/11 13:02:35 INFO : cache: deleted (0) chunks
2017/12/11 13:03:35 INFO : cache: deleted (0) chunks
2017/12/11 13:04:36 INFO : cache: deleted (0) chunks
2017/12/11 13:05:36 INFO : cache: deleted (0) chunks
2017/12/11 13:08:25 INFO : cache: deleted (0) chunks
2017/12/11 13:09:30 INFO : cache: deleted (0) chunks
2017/12/11 13:10:59 INFO : cache: deleted (0) chunks
2017/12/11 13:17:25 INFO : cache: deleted (0) chunks
2017/12/11 13:17:25 INFO : cache: deleted (0) entries
2017/12/11 13:23:51 INFO : cache: deleted (0) chunks
2017/12/11 13:28:01 INFO : cache: deleted (0) chunks
2017/12/11 13:29:02 INFO : cache: deleted (0) chunks
2017/12/11 13:47:27 INFO : cache: deleted (0) chunks
2017/12/11 13:47:27 INFO : cache: deleted (0) entries
2017/12/11 13:55:57 INFO : cache: deleted (0) chunks
2017/12/11 14:01:48 INFO : cache: deleted (0) chunks
2017/12/11 14:10:02 INFO : cache: deleted (0) chunks
2017/12/11 14:10:02 INFO : cache: deleted (2455) entries
2017/12/11 14:11:02 INFO : cache: deleted (0) chunks
Mounted at 13:00 CET, checked directory and file count about every 5 minutes.
[206 directories, 1464 files] between 13:00 and 14:10 CET [206 directories, 942 files] 522 files disappeared at ~ 14:10 CET
File Age set to 1h
At 14:45 CET I moved a new movie onto the drive (with rclone move, not cache) and it’s not listed yet at 15:22 CET, 2 more files are gone instead, the stats are now [206 directories, 940 files]
It must indeed have something to do with File Age.
2017/12/11 17:02:49 INFO : plexcache: Connected to Plex server: http://127.0.0. 1:32543
2017/12/11 17:02:49 INFO : plexcache: Storage DB path: /home/dellinger/.cache/r clone/cache-backend/plexcache.db
2017/12/11 17:02:49 INFO : plexcache: Chunk Memory: true
2017/12/11 17:02:49 INFO : plexcache: Chunk Size: 40M
2017/12/11 17:02:49 INFO : plexcache: Chunk Total Size: 1000G
2017/12/11 17:02:49 INFO : plexcache: Chunk Clean Interval: 1m0s
2017/12/11 17:02:49 INFO : plexcache: Workers: 1
2017/12/11 17:02:49 INFO : plexcache: File Age: 15m0s
2017/12/11 17:02:49 INFO : plexcache: Cache Writes: false
2017/12/11 17:02:49 INFO : cache: deleted (0) chunks
2017/12/11 17:02:49 INFO : cache: deleted (0) entries
2017/12/11 17:02:50 INFO : plexcache: Connected to Plex server: http://127.0.0. 1:32543
2017/12/11 17:02:50 INFO : plexcache: Storage DB path: /home/dellinger/.cache/r clone/cache-backend/plexcache.db
2017/12/11 17:02:50 INFO : plexcache: Chunk Memory: true
2017/12/11 17:02:50 INFO : plexcache: Chunk Size: 40M
2017/12/11 17:02:50 INFO : plexcache: Chunk Total Size: 1000G
2017/12/11 17:02:50 INFO : plexcache: Chunk Clean Interval: 1m0s
2017/12/11 17:02:50 INFO : plexcache: Workers: 1
2017/12/11 17:02:50 INFO : plexcache: File Age: 15m0s
2017/12/11 17:02:50 INFO : plexcache: Cache Writes: false
2017/12/11 17:02:50 INFO : Encrypted drive 'plexdrive:/': Modify window is 1ms
2017/12/11 17:02:50 INFO : cache: deleted (0) chunks
2017/12/11 17:02:50 NOTICE: Encrypted drive 'plexdrive:/': poll-interval is not supported by this remote
2017/12/11 17:02:50 INFO : cache: deleted (0) entries
2017/12/11 17:03:50 INFO : cache: deleted (0) chunks
2017/12/11 17:04:51 INFO : cache: deleted (0) chunks
2017/12/11 17:05:51 INFO : cache: deleted (0) chunks
2017/12/11 17:06:35 INFO : cache: deleted (0) entries
2017/12/11 17:06:51 INFO : cache: deleted (0) chunks
2017/12/11 17:21:47 INFO : cache: deleted (0) chunks
2017/12/11 17:21:47 INFO : cache: deleted (2376) entries
2017/12/11 17:22:47 INFO : cache: deleted (0) chunks
I’ve set it to 15min for my most recent test and the files disappeared about 15min after mounting.
I’m still trying to get to the cause or at least replicate this issue but I don’t have any success. I did the exact same steps described here.
The deletion logs don’t mean the files are deleted but just that their info is evicted from cache and at the next list or search of an object it will be read from the cloud provider, not from cache.
Are you all mapping drive -> cache -> crypt? Do you use any other tools in between or outside of these mounts that could interfere?
I have the same problem with encryption but for simplicity, I’m only using unencrypted right now. I’m not using anything else like UnionFS, etc.
It happens with and without crypt. I’m no longer using crypt for testing just to eliminate that level but the problem is on both.
I also don’t use anything special.
GDrive > Cache > Crypt , no unionfs etc.
As I already mentioned above, after “info age” passed by, a lot of files are gone and new files moved to the cloud drive in the meantime are not getting recognized after that time too.
I have to stop rclone and restart with db-purge to get back the lost files and the new folders and files I moved to gdrive.
I didn’t try without crypt, but I’ll do some more testing after work.
There are no troubles with rclone mount without the cache feature (except the speed and bans during plex scans)
I concur with @Shacuih. Some problem whether its:
Google > Cache or
Google > Cache > Crypt
For me. Obviously, the cache-purge is OK (we can debate what the “optimal” value is) but it doesn’t look like it is correctly re-caching existing files that expired or new files that have been added.
I also can confirm that restarting with db-purge (which is now basically how I always start it) does work to bring things back, albeit temporarily.
I’ve just mounted my crypted cache with:
rclonebeta mount --allow-other gcache: /media/cache/
Mount is ok but i have this Notice.
What does it mean?
NOTICE: Encrypted drive ‘gcache:’: poll-interval is not supported by this remote
I just finished testing Cache with a non-crypt drive.
For me it shows the same behaviour as with encrypted drive.
I think you can duplicate the problem easily by mounting the rclone cache to, say, /mnt/rclone and then:
ls -R /mnt/rclone
This should scan every directory and conceivably cache it. Then, try it again. You’ll see a lot fewer files and many empty or near-empty directories.
Also, not sure if its related, but that scan takes longer and longer each time you do it unless you reboot (simply killing the daemon doesn’t work). Memory leak?
I did with “date && tree /path/to/mount|grep directories”
with info age set to 10m, 904 files disappeared after these 10 Minutes, no encrypted drive this time.
moved ~ 20 new folders/files to the drive at 15:52 CET, but were not recognized, see output:
Wed Dec 13 15:36:22 CET 2017
421 directories, 2379 files
Wed Dec 13 15:45:20 CET 2017
421 directories, 2379 files
Wed Dec 13 15:50:22 CET 2017
421 directories, 1475 files
Wed Dec 13 15:57:47 CET 2017
421 directories, 1475 files
Wed Dec 13 16:02:48 CET 2017
421 directories, 1475 files
Wed Dec 13 16:10:21 CET 2017
421 directories, 1475 files
Wed Dec 13 16:15:22 CET 2017
421 directories, 1475 files
Wed Dec 13 16:23:00 CET 2017
421 directories, 1475 files
Wed Dec 13 16:28:01 CET 2017
421 directories, 1475 files
Wed Dec 13 16:35:31 CET 2017
421 directories, 1475 files
Wed Dec 13 16:40:32 CET 2017
421 directories, 1475 files
Wed Dec 13 16:47:57 CET 2017
421 directories, 1475 files
Wed Dec 13 16:52:58 CET 2017
421 directories, 1475 files
Wed Dec 13 17:00:14 CET 2017
421 directories, 1475 files
Wed Dec 13 17:05:15 CET 2017
421 directories, 1475 files
Wed Dec 13 17:12:42 CET 2017
421 directories, 1475 files
Wed Dec 13 17:17:43 CET 2017
421 directories, 1475 files
Wed Dec 13 17:25:03 CET 2017
421 directories, 1475 files
Wed Dec 13 17:30:04 CET 2017
421 directories, 1475 files
Wed Dec 13 17:37:23 CET 2017
421 directories, 1475 files
Wed Dec 13 17:42:24 CET 2017