Files currently in tmp_upload_path no longer show up in mount. Bug?

MaxC · June 25, 2019, 11:33pm

Summary

After re-mounting a cache remote, the files still in tmp_upload_path resume uploading, but aren't showing up in the mount. Only files already uploaded show up.

Full Story

In an effort to build a B2-backed infinite storage box, I wanted to choose a path of least resistance and go with the simple rclone cache mount.

Say I have 600GB in MyFiles. I did this:

mv MyFiles MyFilesBackup
mount rclone cache over MyFiles
mv MyFilesBackup/* MyFiles

I observed how all the files were added to the tmp_upload_path dir as expected. I had delay set to 1 month, because I wanted most newly added files to sit locally, so nothing was uploading yet.

Then I realized that I want the initial bulk to start uploading immediately, and later switch to 1 month, so I unmounted the cache, changed delay to 1 minute, and re-mounted the cache, to trigger immediate upload. It worked, I observed logged upload activity.

Then I had to get on a video meeting, and to get more bandwidth I unmounted the cache to stop the uploads. It was taking a while (log said something like "closing cleanup" and was blocking), but because my unmount was systemd-controlled, it timed out and sigkilled it (-9).

So after the meeting, I remounted the cache. And now I only see 5 directories out of 50. They are all still in tmp_upload_path, but no longer show up in mounted cache. Is this a bug?

Despite not showing up, the uploads resumed. I can see rclone uploading files in tmp_upload_path, but just not showing them in the mounted dir.

Info

OS: Ubuntu 18.04 LTS
Rclone: v1.48.0

(Everything in <brackets> is cut out for this post)

rclone.conf

[B2]
type = b2
account = <account>
key = <key>
endpoint =

[B2C]
type = cache
remote = B2:Reserve
chunk_size = 10M
info_age = 1w
chunk_total_size = 1.200T
tmp_upload_path = <path>
tmp_wait_time = 1m

cache-mount.service

[Unit]
Description=B2 Cache Mount
After=network-online.target
Wants=network-online.target

[Service]
TimeoutStartSec=10
ExecStart=/usr/bin/rclone mount B2C:Reserve/<RemotePath> /<home>/MyFiles \
   --config /<home>/.config/rclone/rclone.conf \
   --fast-list \
   --allow-other \
   --dir-cache-time=24h \
   --cache-workers=5 \
   --buffer-size 0M \
   --umask 002 \
   --log-level INFO
ExecStop=/bin/fusermount -uz /<home>/MyFiles
Restart=always
RestartSec=10
User=<user>
Group=<group>

[Install]
WantedBy=multi-user.target

ncw · June 26, 2019, 6:44am

b2 doesn't support changes notifications (unlike drive) so I suspect that the files will turn up after --dir-cache-time has expired.

  --dir-cache-time duration                Time to cache directory entries for. (default 5m0s)

Well that is the expected behaviour without using the cache backend and I think it should be the same with the cache backend.. If it isn't then it is probably a bug.

ncw · June 26, 2019, 6:45am

Come to think of it, cache has had the most use with google drive which does support changenotify so it might be that no-one has ever noticed this before because of that.

MaxC · June 26, 2019, 7:02am

Thanks for your hard work in maintaining this lib and replying here so consistently. That makes a lot of sense (and I will verify this tomorrow), however a gut feeling tells me there’s a bug in there. Specifically, if dir cache somehow cached an incomplete file list, it must have been reported to it in such an incomplete form by the cache remote at some point. However, based on the steps I took, there was never a situation where the cache remote would’ve been confused about what files it has. I only interacted with it by moving files directly into it, which should be invalidating both mount dir cache, and remote info cache. Any thoughts on this?

MaxC · June 26, 2019, 7:11am

I’m not near a computer at this moment, but my naive/speculative steps to reproduce might look like this:

Create a B2 cache remote with tmp upload path, and set upload wait time to 1 month
Mount the b2 cache remote
Copy some files into it and make sure they went into tmp upload dir
Unmount the cache remote
Mount the cache remote again, are the files there that were added in step 3? If not: must be a bug.

ncw · June 26, 2019, 8:47am

If you can make a simple reproduction I can try, that would be great.

I'm not 100% sure what is going on but a reproduction is the next step in finding out!

MaxC · June 26, 2019, 6:45pm

Ok bug reproduced.

Summary: Any directory sitting in tmp_upload_path (even non-empty) will not appear in the mounted cache remote upon re-mounting. Only files appear in the mount.

Here are the steps to reproduce.

Step 1. Create these rclone.conf remotes

Note: Replace <bracket> values with your own.

[B2]
type = b2
account = <account>
key = <key>
endpoint =

[B2CacheBug]
type = cache
remote = B2:<bucket>/CacheBug
chunk_size = 10M
info_age = 1w
chunk_total_size = 10G
tmp_upload_path = /<home>/.cache/rclone/uploads_cache_bug
tmp_wait_time = 720h

Step 2. Mount the cache remote

Note: Replace <bracket> values with your own.

~$ mkdir CacheBug
~$ rclone mount B2CacheBug: /<home>/CacheBug --config /<home>/.config/rclone/rclone.conf --fast-list --allow-other --dir-cache-time=24h --cache-workers=5 --buffer-size 0M --umask 002 --log-level INFO

Leave this terminal on to observe logs.

Step 3. In another terminal, add a file and a dir with a file

~$ echo "hello world" > text_file.txt
~$ mkdir test_dir
~$ echo "hello world" > test_dir/text_file.txt
~$ mv text_file.txt CacheBug/
~$ mv test_dir CacheBug/
~$ ls CacheBug
test_dir  text_file.txt

Step 4. Check to ensure that both file and dir are in tmp upload path

~$ ls ~/.cache/rclone/uploads_cache_bug/
test_dir  text_file.txt

~$ tree ~/.cache/rclone/uploads_cache_bug/
~/.cache/rclone/uploads_cache_bug/
├── test_dir
│   └── text_file.txt
└── text_file.txt

Step 5. Unmount the cache remote and mount it again

Press CTRL+C in the mount terminal and wait for unmount
Press up arrow and enter to run the mount command again

Step 6. Check files in the mounted path

~$ ls ~/CacheBug/
text_file.txt

There is no longer test_dir in here, only the file.

Animosity022 · June 26, 2019, 7:12pm

Can you do that with DEBUG? I ran your same steps and doesn't work to reproduce it for me.

Animosity022 · June 26, 2019, 7:17pm

On the second debug log, you should see something like this:

2019/06/26 15:12:28 DEBUG : text_file.txt: pending upload found
2019/06/26 15:12:28 DEBUG : : list: warm 3 from cache for: , expiring on: 2019-06-27 15:11:55.379043089 -0400 EDT
2019/06/26 15:12:28 DEBUG : : list: cached entries: [media test_dir text_file.txt]
2019/06/26 15:12:28 DEBUG : /: >ReadDirAll: item=3, err=<nil>
2019/06/26 15:12:28 DEBUG : /: Lookup: name="media"
2019/06/26 15:12:28 DEBUG : /: >Lookup: node=media/, err=<nil>

MaxC · June 26, 2019, 7:34pm

FIRST MOUNT STARTED

------------

2019/06/26 15:15:55 DEBUG : B2CacheBug: wrapped B2:Reserve/CacheBug/ at root
2019/06/26 15:15:55 INFO  : B2CacheBug: Cache DB path: /home/htpc/.cache/rclone/cache-backend/B2CacheBug.db
2019/06/26 15:15:55 INFO  : B2CacheBug: Cache chunk path: /home/htpc/.cache/rclone/cache-backend/B2CacheBug
2019/06/26 15:15:55 INFO  : B2CacheBug: Chunk Memory: true
2019/06/26 15:15:55 INFO  : B2CacheBug: Chunk Size: 10M
2019/06/26 15:15:55 INFO  : B2CacheBug: Chunk Total Size: 10G
2019/06/26 15:15:55 INFO  : B2CacheBug: Chunk Clean Interval: 1m0s
2019/06/26 15:15:55 INFO  : B2CacheBug: Workers: 5
2019/06/26 15:15:55 INFO  : B2CacheBug: File Age: 1w
2019/06/26 15:15:55 INFO  : B2CacheBug: Upload Temp Rest Time: 1M
2019/06/26 15:15:55 INFO  : B2CacheBug: Upload Temp FS: /home/htpc/.cache/rclone/uploads_cache_bug
2019/06/26 15:15:55 DEBUG : Adding path "cache/expire" to remote control registry
2019/06/26 15:15:55 DEBUG : Adding path "cache/stats" to remote control registry
2019/06/26 15:15:55 DEBUG : Adding path "cache/fetch" to remote control registry
2019/06/26 15:15:55 DEBUG : Cache remote B2CacheBug:: Mounting on "/home/htpc/CacheBug"
2019/06/26 15:15:55 INFO  : Cache remote B2CacheBug:: poll-interval is not supported by this remote
2019/06/26 15:15:55 DEBUG : Adding path "vfs/forget" to remote control registry
2019/06/26 15:15:55 DEBUG : Adding path "vfs/refresh" to remote control registry
2019/06/26 15:15:55 DEBUG : Adding path "vfs/poll-interval" to remote control registry

------------

ADDED text_file.txt

2019/06/26 15:16:55 DEBUG : Cache remote B2CacheBug:: starting cleanup
2019/06/26 15:17:07 DEBUG : /: Attr:
2019/06/26 15:17:07 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:17:08 DEBUG : /: ReadDirAll:
2019/06/26 15:17:08 DEBUG : /: >ReadDirAll: item=0, err=<nil>
2019/06/26 15:17:45 DEBUG : /: Attr:
2019/06/26 15:17:45 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:17:45 DEBUG : /: Lookup: name="text_file.txt"
2019/06/26 15:17:45 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:45 DEBUG : /: Lookup: name="text_file.txt"
2019/06/26 15:17:45 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:45 DEBUG : /: Lookup: name="text_file.txt"
2019/06/26 15:17:45 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:45 DEBUG : /: Create: name="text_file.txt"
2019/06/26 15:17:45 DEBUG : text_file.txt: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2019/06/26 15:17:45 DEBUG : text_file.txt: >Open: fd=text_file.txt (w), err=<nil>
2019/06/26 15:17:45 DEBUG : /: >Create: node=text_file.txt, handle=&{text_file.txt (w)}, err=<nil>
2019/06/26 15:17:45 DEBUG : text_file.txt: Attr:
2019/06/26 15:17:45 DEBUG : text_file.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: Write: len=12, offset=0
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: >Write: written=12, err=<nil>
2019/06/26 15:17:45 DEBUG : text_file.txt: Setattr: a=Setattr [ID=0x71 Node=0x2 Uid=1000 Gid=1000 Pid=379] atime=2019-06-26 15:17:30.625286426 -0400 EDT mtime=2019-06-26 15:17:30.625286426 -0400 EDT handle=INVALID-0x0
2019/06/26 15:17:45 DEBUG : text_file.txt: >Setattr: err=<nil>
2019/06/26 15:17:45 DEBUG : text_file.txt: Attr:
2019/06/26 15:17:45 DEBUG : text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:17:45 DEBUG : text_file.txt: Setattr: a=Setattr [ID=0x73 Node=0x2 Uid=1000 Gid=1000 Pid=379] mode=-rw-rw-r-- handle=INVALID-0x0
2019/06/26 15:17:45 DEBUG : text_file.txt: >Setattr: err=<nil>
2019/06/26 15:17:45 DEBUG : text_file.txt: Attr:
2019/06/26 15:17:45 DEBUG : text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: Flush:
2019/06/26 15:17:45 DEBUG : Cache remote B2CacheBug:: File to upload is small (12 bytes), uploading instead of streaming
2019/06/26 15:17:45 DEBUG : Cache remote B2CacheBug:: put data at 'text_file.txt'
2019/06/26 15:17:45 DEBUG : : cache: expired
2019/06/26 15:17:45 INFO  : text_file.txt: put: uploaded in temp fs
2019/06/26 15:17:45 INFO  : text_file.txt: put: queued for upload
2019/06/26 15:17:45 DEBUG : text_file.txt: pending upload found
2019/06/26 15:17:45 DEBUG : text_file.txt: put: added to cache
2019/06/26 15:17:45 DEBUG : : cache: expired
2019/06/26 15:17:45 INFO  : : put: cache expired
2019/06/26 15:17:45 DEBUG : text_file.txt: object hash cached: 22596363b3de40b06f981fb85d82312e8c0ed511
2019/06/26 15:17:45 INFO  : text_file.txt: Copied (new)
2019/06/26 15:17:45 DEBUG : text_file.txt: updated ModTime: 2019-06-26 15:17:30.625286426 -0400 EDT
2019/06/26 15:17:45 DEBUG : text_file.txt: File.applyPendingModTime OK
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: >Flush: err=<nil>
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: Release:
2019/06/26 15:17:45 DEBUG : text_file.txt: WriteFileHandle.Release nothing to do
2019/06/26 15:17:45 DEBUG : &{text_file.txt (w)}: >Release: err=<nil>

ADDED test_dir

2019/06/26 15:17:55 DEBUG : Cache remote B2CacheBug:: starting cleanup
2019/06/26 15:17:59 DEBUG : /: Attr:
2019/06/26 15:17:59 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:17:59 DEBUG : /: Lookup: name="test_dir"
2019/06/26 15:17:59 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:59 DEBUG : /: Lookup: name="test_dir"
2019/06/26 15:17:59 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:59 DEBUG : /: Lookup: name="test_dir"
2019/06/26 15:17:59 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:17:59 DEBUG : /: Mkdir: name="test_dir"
2019/06/26 15:17:59 DEBUG : Cache remote B2CacheBug:: mkdir 'test_dir'
2019/06/26 15:17:59 DEBUG : test_dir: mkdir: created dir in source fs
2019/06/26 15:17:59 DEBUG : test_dir: mkdir: added to cache
2019/06/26 15:17:59 DEBUG : : cache: expired
2019/06/26 15:17:59 INFO  : : mkdir: cache expired
2019/06/26 15:17:59 DEBUG : /: >Mkdir: node=test_dir/, err=<nil>
2019/06/26 15:17:59 DEBUG : test_dir/: Attr:
2019/06/26 15:17:59 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:17:59 DEBUG : test_dir/: Lookup: name="text_file.txt"
2019/06/26 15:17:59 DEBUG : Cache remote B2CacheBug:: list 'test_dir'
2019/06/26 15:17:59 DEBUG : test_dir: list: empty listing
2019/06/26 15:17:59 DEBUG : test_dir: list: read 0 from temp fs
2019/06/26 15:17:59 DEBUG : test_dir: list: temp fs entries: []
2019/06/26 15:18:00 DEBUG : test_dir: list: read 0 from source
2019/06/26 15:18:00 DEBUG : test_dir: list: source entries: []
2019/06/26 15:18:00 DEBUG : test_dir: list: cached directories: 0
2019/06/26 15:18:00 DEBUG : test_dir: list: cached dir: 'test_dir', cache ts: 2019-06-26 15:18:00.404331891 -0400 EDT m=+126.022211692
2019/06/26 15:18:00 DEBUG : test_dir/: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:00 DEBUG : test_dir/: Lookup: name="text_file.txt"
2019/06/26 15:18:00 DEBUG : test_dir/: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:00 DEBUG : test_dir/: Create: name="text_file.txt"
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Open: fd=test_dir/text_file.txt (w), err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: >Create: node=test_dir/text_file.txt, handle=&{test_dir/text_file.txt (w)}, err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: Write: len=12, offset=0
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: >Write: written=12, err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Setattr: a=Setattr [ID=0x7f Node=0x4 Uid=1000 Gid=1000 Pid=381] atime=2019-06-26 15:17:40.501285357 -0400 EDT mtime=2019-06-26 15:17:40.501285357 -0400 EDT handle=INVALID-0x0
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Setattr: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Setattr: a=Setattr [ID=0x80 Node=0x4 Uid=1000 Gid=1000 Pid=381] mode=-rw-rw-r-- handle=INVALID-0x0
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Setattr: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: Flush:
2019/06/26 15:18:00 DEBUG : Cache remote B2CacheBug:: File to upload is small (12 bytes), uploading instead of streaming
2019/06/26 15:18:00 DEBUG : Cache remote B2CacheBug:: put data at 'test_dir/text_file.txt'
2019/06/26 15:18:00 DEBUG : test_dir: cache: expired test_dir
2019/06/26 15:18:00 DEBUG : test_dir: cache: expired
2019/06/26 15:18:00 INFO  : test_dir/text_file.txt: put: uploaded in temp fs
2019/06/26 15:18:00 INFO  : test_dir/text_file.txt: put: queued for upload
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: pending upload found
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: put: added to cache
2019/06/26 15:18:00 DEBUG : test_dir: cache: expired test_dir
2019/06/26 15:18:00 DEBUG : test_dir: cache: expired
2019/06/26 15:18:00 INFO  : test_dir: put: cache expired
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: object hash cached: 22596363b3de40b06f981fb85d82312e8c0ed511
2019/06/26 15:18:00 INFO  : test_dir/text_file.txt: Copied (new)
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: updated ModTime: 2019-06-26 15:17:40.501285357 -0400 EDT
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: File.applyPendingModTime OK
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: >Flush: err=<nil>
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: Release:
2019/06/26 15:18:00 DEBUG : test_dir/text_file.txt: WriteFileHandle.Release nothing to do
2019/06/26 15:18:00 DEBUG : &{test_dir/text_file.txt (w)}: >Release: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Setattr: stat=Setattr [ID=0x83 Node=0x3 Uid=1000 Gid=1000 Pid=381] atime=2019-06-26 15:17:36.42528576 -0400 EDT mtime=2019-06-26 15:17:40.501285357 -0400 EDT handle=INVALID-0x0
2019/06/26 15:18:00 DEBUG : test_dir/: >Setattr: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Setattr: stat=Setattr [ID=0x84 Node=0x3 Uid=1000 Gid=1000 Pid=381] uid=1000 gid=1000 handle=INVALID-0x0
2019/06/26 15:18:00 DEBUG : test_dir/: >Setattr: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Setattr: stat=Setattr [ID=0x85 Node=0x3 Uid=1000 Gid=1000 Pid=381] mode=drwxrwxr-x handle=INVALID-0x0
2019/06/26 15:18:00 DEBUG : test_dir/: >Setattr: err=<nil>
2019/06/26 15:18:00 DEBUG : test_dir/: Attr:
2019/06/26 15:18:00 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:19 DEBUG : /: Attr:
2019/06/26 15:18:19 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:19 DEBUG : /: ReadDirAll:
2019/06/26 15:18:19 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2019/06/26 15:18:19 DEBUG : /: Lookup: name="test_dir"
2019/06/26 15:18:19 DEBUG : /: >Lookup: node=test_dir/, err=<nil>
2019/06/26 15:18:19 DEBUG : test_dir/: Attr:
2019/06/26 15:18:19 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:19 DEBUG : /: Lookup: name="test_dir"
2019/06/26 15:18:19 DEBUG : /: >Lookup: node=test_dir/, err=<nil>
2019/06/26 15:18:19 DEBUG : test_dir/: Attr:
2019/06/26 15:18:19 DEBUG : test_dir/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:19 DEBUG : text_file.txt: Attr:
2019/06/26 15:18:19 DEBUG : text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>
^C

UNMOUNTED

MOUNTED AGAIN

------------

2019/06/26 15:18:39 DEBUG : B2CacheBug: wrapped B2:Reserve/CacheBug/ at root
2019/06/26 15:18:39 INFO  : B2CacheBug: Cache DB path: /home/htpc/.cache/rclone/cache-backend/B2CacheBug.db
2019/06/26 15:18:39 INFO  : B2CacheBug: Cache chunk path: /home/htpc/.cache/rclone/cache-backend/B2CacheBug
2019/06/26 15:18:39 INFO  : B2CacheBug: Chunk Memory: true
2019/06/26 15:18:39 INFO  : B2CacheBug: Chunk Size: 10M
2019/06/26 15:18:39 INFO  : B2CacheBug: Chunk Total Size: 10G
2019/06/26 15:18:39 INFO  : B2CacheBug: Chunk Clean Interval: 1m0s
2019/06/26 15:18:39 INFO  : B2CacheBug: Workers: 5
2019/06/26 15:18:39 INFO  : B2CacheBug: File Age: 1w
2019/06/26 15:18:39 INFO  : B2CacheBug: Upload Temp Rest Time: 1M
2019/06/26 15:18:39 INFO  : B2CacheBug: Upload Temp FS: /home/htpc/.cache/rclone/uploads_cache_bug
2019/06/26 15:18:39 DEBUG : Adding path "cache/expire" to remote control registry
2019/06/26 15:18:39 DEBUG : Adding path "cache/stats" to remote control registry
2019/06/26 15:18:39 DEBUG : Adding path "cache/fetch" to remote control registry
2019/06/26 15:18:39 DEBUG : Cache remote B2CacheBug:: Mounting on "/home/htpc/CacheBug"
2019/06/26 15:18:39 INFO  : Cache remote B2CacheBug:: poll-interval is not supported by this remote
2019/06/26 15:18:39 DEBUG : Adding path "vfs/forget" to remote control registry
2019/06/26 15:18:39 DEBUG : Adding path "vfs/refresh" to remote control registry
2019/06/26 15:18:39 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2019/06/26 15:18:39 DEBUG : : Root:
2019/06/26 15:18:39 DEBUG : : >Root: node=/, err=<nil>
2019/06/26 15:18:39 DEBUG : /: Lookup: name=".Trash"
2019/06/26 15:18:39 DEBUG : Cache remote B2CacheBug:: list ''
2019/06/26 15:18:39 DEBUG : text_file.txt: pending upload found
2019/06/26 15:18:39 DEBUG : : list: cold listing: 2019-06-19 15:18:00.416133011 -0400 EDT
2019/06/26 15:18:39 DEBUG : : list: read 1 from temp fs
2019/06/26 15:18:39 DEBUG : : list: temp fs entries: [text_file.txt]
2019/06/26 15:18:39 DEBUG : text_file.txt: pending upload found
2019/06/26 15:18:39 DEBUG : text_file.txt: list: cached temp object
2019/06/26 15:18:39 DEBUG : /: Attr:
2019/06/26 15:18:39 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : : list: read 0 from source
2019/06/26 15:18:40 DEBUG : : list: source entries: []
2019/06/26 15:18:40 DEBUG : : list: remove entry: test_dir
2019/06/26 15:18:40 DEBUG : : list: remove entry: text_file.txt
2019/06/26 15:18:40 DEBUG : : list: cached directories: 0
2019/06/26 15:18:40 DEBUG : : list: cached dir: '', cache ts: 2019-06-26 15:18:40.148800159 -0400 EDT m=+1.807914771
2019/06/26 15:18:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:40 DEBUG : /: Lookup: name=".xdg-volume-info"
2019/06/26 15:18:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:40 DEBUG : /: Lookup: name="autorun.inf"
2019/06/26 15:18:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Lookup: name=".Trash-1000"
2019/06/26 15:18:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Attr:
2019/06/26 15:18:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:40 DEBUG : /: ReadDirAll:
2019/06/26 15:18:40 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:40 DEBUG : /: Lookup: name="autorun.inf"
2019/06/26 15:18:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2019/06/26 15:18:50 DEBUG : /: Attr:
2019/06/26 15:18:50 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/06/26 15:18:50 DEBUG : /: ReadDirAll:
2019/06/26 15:18:50 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2019/06/26 15:18:50 DEBUG : /: Lookup: name="text_file.txt"
2019/06/26 15:18:50 DEBUG : /: >Lookup: node=text_file.txt, err=<nil>

ls CacheBug/

2019/06/26 15:18:50 DEBUG : text_file.txt: Attr:
2019/06/26 15:18:50 DEBUG : text_file.txt: >Attr: a=valid=1s ino=0 size=12 mode=-rw-rw-r--, err=<nil>

MaxC · June 26, 2019, 7:45pm

Looks like it's almost like that, but not quite. Not sure what my output suggests.

ncw · June 26, 2019, 7:57pm

Hmm... It would be good to find out why you and @Animosity022 are getting different results.

Did you use the same mount command @Animosity022?

MaxC · June 27, 2019, 3:30am

FWIW, I tried to restart my mount with dir cache dialed down to 1 minute, and after multiple minutes of running ls in the mount, the missing dirs didn't appear. I confirmed again that they're all in tmp_upload_path. I also have info_age set to 1 week in the cache remote config, and I have not yet tried changing that.

MaxC · June 27, 2019, 5:02am

Now have both info_age and dir_cache set to 1 minute, and after a bunch of minutes of ls-ing the mount, still the dirs from tmp_upload_path don't show up.

ncw · June 27, 2019, 8:58am

I managed to replicate the problem using your instructions - thank you

I think this is a combination of two issues

there is a design flaw in the cache backend which means it doesn't store pending directories in its internal db, only pending files
normally this would be fine since the cache backend creates the directories immediately, however in the case of b2, you can't have empty directories on b2 which means this scheme fails.

I tested this hypothesis by adding an additional step, I created the test_dir directory on b2 in advance by copying a file to it

rclone copyto text_file.txt b2:BUCKET/CacheBug/test_dir/keeper_file.txt

If I run your test then it works fine after that.

/
├── test_dir
│   ├── keeper_file.txt
│   └── text_file.txt
└── text_file.txt

Do you think that is correct?

MaxC · June 27, 2019, 3:55pm

This is spot on. It explains everything.

Yes, if a directory exists remotely, it shows up. I see every dir that finished uploading from tmp_upload_path, but don't see any dir that's still pending in tmp_upload_path.

There is another small factor that may have helped hide this flaw: if you never unmount the cache remote after the first mount, and just add dirs into it, the dirs are there. (Albeit maybe that was an artifact of long dir_cache, or long info_age).

So in an effort to figure out a direction to fix it:

Would it make sense to allow the db to store paths to files anywhere in tmp_upload_path, not just at the top level? This way it can continue ignoring empty dirs, but if a dir has files, then that subtree will show up in the mount.

MaxC · June 27, 2019, 6:36pm

Somewhat offtopic, but here's my argument on why this is worth fixing. B2 is the ideal remote for rclone when it comes to price/usability and intended use. Of course GDrive and friends can be used, but that's not quite what their unlimited plans are intended for, which is reflected in their API caps, and other terms of use restrictions, which all stem from unsustainable pricing. B2 is the cheapest of unlimited sustainably-priced services (such as S3, Glacier, Azure, etc) that don't cap your interactions, just charge appropriately for them, which is perfect for busy people who need unbounded storage without extra hassle.

ncw · June 27, 2019, 9:53pm

I think the next step would be to make a new issue on github with a link to the forum and a summary of the findings.

Do you fancy trying to help fix this?

MaxC · June 27, 2019, 11:42pm

@ncw Issue posted. However, I've never written Go before. For now I won't claim this issue in case someone might be able to tackle it. However, I might explore the code a bit. If I end up actually working on it, I'll promptly leave an issue comment. Always happy to help on architectural discussion/decisions.

ncw · June 28, 2019, 6:51am

Thanks for that! I added the repro to the issue. The cache backend is a bit unmaintained at the moment as the original author isn't available so any help much appreciated!