Can I add directory updates to the rclone log?

brimur · November 10, 2023, 2:52pm

Version: rclone v1.62.2

Mount:
--allow-other --rc  --cache-dir=/mnt/external/rclone/cache --vfs-cache-mode full --vfs-cache-max-size 1450G --vfs-cache-max-age 30w -vv --log-file=/logs/rclone.log --vfs-fast-fingerprint --dir-cache-time 10s

Just a question. I have two servers at different locations using the same cloud drive mounted with rclone and everything is working as expected but I have been asked to notify an application of directory changes when they happen such as a folder being created or deleted. My understanding is rclone/FUSE does not use inotify so I was hoping the rclone logs might have that info. The mounts are using DEBUG (-vv) but when I run the commands below on the servers I can do a LS and do see the directories deleted and created on both servers so its working. I see many things in the logs (mostly DEBUG : vfs cache RemoveNotInUse) but nothing shows in the logs about a new folder being created or deleted. Can that be added somehow or seen somewhere else?

Thanks

Server 1: mkdir myDIR && rmdir myDIR
Server 2: tail -f  /logs/rclone.log | grep myDIR

kapitainsky · November 10, 2023, 4:27pm

You are using old rclone version
What is your remote?

brimur · November 10, 2023, 4:33pm

Thanks I have updated. The remote is a Box account. I suppose I was asking if rclone keeps track of changes in the directory tree or addition of new files?

2023/11/10 16:32:28 NOTICE: Successfully updated rclone from version v1.62.2 to version v1.64.2

kapitainsky · November 10, 2023, 4:48pm

Both my questions were related:)

As you use Box the good news is that since v1.64 of rclone Box remote supports polling

It means that now your mount should poll for changes every 1min (--poll-interval) and you should see some info in DEBUG log about any directory changes.

I do not have box account but see below from onedrive which also supports polling:

I created new directory onedrive:test_directory using web GUI and within 1min this is what I can see in DEBUG mount log:

2023/11/10 16:53:56 DEBUG : OneDrive root '': Checking for changes on remote
2023/11/10 16:53:56 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/10 16:53:56 DEBUG : : changeNotify: relativePath="root", type=0
2023/11/10 16:53:56 DEBUG : : invalidating directory cache
2023/11/10 16:53:56 DEBUG : : >changeNotify:
2023/11/10 16:53:56 DEBUG : : changeNotify: relativePath="test_directory", type=0
2023/11/10 16:53:56 DEBUG : : >changeNotify:

So watching log and lines with changeNotify I can get what is needed.

brimur · November 13, 2023, 1:23pm

Thats fantastic! Thanks I'll check that out!

brimur · November 13, 2023, 2:00pm

I dont think it is working or I am using it wrong. I added --poll-interval 60s and --dir-cache-time 9999h on both my servers and rebooted. After a reboot I started a tail -f rclone.log. On one server I went to the root directory of my mount and created a directory called myDir and a file called myFile.txt. Then two more files. On the other server I am repeatedly doing an 'ls' command but the new files are not showing up.

I also do not see any mention of "DEBUG : OneDrive root '': Checking for changes on remote" that you have in your logs. All I get is this...

2023/11/13 13:53:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size 87.844Gi (was 87.844Gi)
2023/11/13 13:54:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size 87.844Gi (was 87.844Gi)
2023/11/13 13:55:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size 87.844Gi (was 87.844Gi)
2023/11/13 13:56:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size 87.844Gi (was 87.844Gi)
2023/11/13 13:57:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size 87.844Gi (was 87.844Gi)

kapitainsky · November 13, 2023, 2:15pm

You are using Box not Onedrive. What are exactly Box polling related logs entries you have to work out yourself. I do not have Box account to test.

I would start with:

tail -f rclone.log | grep "changeNotify"

brimur · November 13, 2023, 2:19pm

Thanks I was just mentioning that I do not see the same as you in terms of info relating to change.
I did a cat rclone.log | grep "changeNotify" and nothing came back at all and the directory still has not updated after 10+ minutes.

the only entries in the log are these repeated every minute...

2023/11/13 14:15:28 DEBUG : vfs cache RemoveNotInUse (maxAge=18144000000000000, emptyOnly=false): item
2023/11/13 14:15:28 INFO  : vfs cache: cleaned: objects 4556 (was 4556) in use 0, to upload 0, uploading 0, total size

Current mount: --allow-other --rc --read-only --cache-dir=/mnt/external/rclone/cache --vfs-cache-mode full --vfs-cache-max-size 1450G --vfs-cache-max-age 30w -vv --log-file=/root/rclone.log --vfs-fast-fingerprint  --dir-cache-time 9999h --no-checksum --poll-interval 60s --use-server-modtime

Animosity022 · November 13, 2023, 2:25pm

That's kind of why we have the template and have some great items in there.

You are on an old version.

That version doesn't have polling support.

You need to upgrade as that's why we ask that exact thing in the help and support template.

brimur · November 13, 2023, 2:27pm

You will see in comment 3 that I updated to v1.64.2. @kapitainsky said that included it?

Animosity022 · November 13, 2023, 2:28pm

I don't see anything as you've again not posted a full debug log but some snippet. Who knows what version you are running with the log? Did you really upgrade it?

kapitainsky · November 13, 2023, 2:34pm

Try to keep logs small. Mount one empty folder you experiment with. So we do not have to search through thousands of lines not related to the key issue.

brimur · November 13, 2023, 2:41pm

Thanks. I have been doing some testing. I think one of my flags is causing an issue. I modified my mount from this...

--allow-other --rc --read-only --cache-dir=/mnt/external/rclone/cache --vfs-cache-mode full --vfs-cache-max-size 1450G --vfs-cache-max-age 30w -vv --log-file=/root/rclone.log --vfs-fast-fingerprint  --dir-cache-time 9999h --no-checksum --poll-interval 60s --use-server-modtime

to this

--allow-other --rc --read-only --cache-dir=/mnt/external/rclone/cache --vfs-cache-mode full --vfs-cache-max-size 1700G --vfs-cache-max-age 1000000h --poll-interval 60s --dir-cache-time 1h -vv --log-file=/root/rclone.log

It is now showing entries in the log when I created myFile4.txt

2023/11/13 14:37:32 DEBUG : box root '': Received 2 events, resulting in 2 paths and 2 notifications
2023/11/13 14:37:32 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997370998950")
2023/11/13 14:37:57 DEBUG : myDIR/: Attr:
2023/11/13 14:37:57 DEBUG : myDIR/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/11/13 14:37:57 DEBUG : myDIR/: ReadDirAll:
2023/11/13 14:37:58 DEBUG : myDIR/myFile.txt: Reset virtual modtime
2023/11/13 14:37:58 DEBUG : myDIR/myFile2.txt: Reset virtual modtime
2023/11/13 14:37:58 DEBUG : myDIR/myFile3.txt: Reset virtual modtime
2023/11/13 14:37:58 DEBUG : myDIR/: >ReadDirAll: item=6, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/: Lookup: name="myFile.txt"
2023/11/13 14:37:58 DEBUG : myDIR/: >Lookup: node=myDIR/myFile.txt, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/myFile.txt: Attr:
2023/11/13 14:37:58 DEBUG : myDIR/myFile.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/: Lookup: name="myFile2.txt"
2023/11/13 14:37:58 DEBUG : myDIR/: >Lookup: node=myDIR/myFile2.txt, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/myFile2.txt: Attr:
2023/11/13 14:37:58 DEBUG : myDIR/myFile2.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/: Lookup: name="myFile3.txt"
2023/11/13 14:37:58 DEBUG : myDIR/: >Lookup: node=myDIR/myFile3.txt, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/myFile3.txt: Attr:
2023/11/13 14:37:58 DEBUG : myDIR/myFile3.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/: Lookup: name="myFile4.txt"
2023/11/13 14:37:58 DEBUG : myDIR/: >Lookup: node=myDIR/myFile4.txt, err=<nil>
2023/11/13 14:37:58 DEBUG : myDIR/myFile4.txt: Attr:
2023/11/13 14:37:58 DEBUG : myDIR/myFile4.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/11/13 14:38:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997370999276")
2023/11/13 14:38:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:39:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371058944")
2023/11/13 14:39:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:40:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371118948")
2023/11/13 14:40:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)

I let it run for a few minutes and created a new file and it showed up which is great. Thanks for your help

2023/11/13 14:38:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997370999276")
2023/11/13 14:38:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:39:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371058944")
2023/11/13 14:39:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:40:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371118948")
2023/11/13 14:40:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:41:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371178942")
2023/11/13 14:41:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:42:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371239008")
2023/11/13 14:42:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:43:31 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371298950")
2023/11/13 14:43:31 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/11/13 14:43:32 DEBUG : : changeNotify: relativePath="myDIR/myFile5.txt.rclone_chunk.001_2mbrzy", type=1
2023/11/13 14:43:32 DEBUG : myDIR: invalidating directory cache
2023/11/13 14:43:32 DEBUG : : >changeNotify:
2023/11/13 14:43:32 DEBUG : : changeNotify: relativePath="myDIR/myFile5.txt", type=1
2023/11/13 14:43:32 DEBUG : : >changeNotify:
2023/11/13 14:43:32 DEBUG : box root '': Received 2 events, resulting in 2 paths and 2 notifications
2023/11/13 14:43:32 DEBUG : box root '': Checking for changes on remote (next_stream_position: "30400997371359030")

system · November 16, 2023, 2:41pm

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.