Yuka
June 10, 2022, 10:28pm
1
I have a mount set up and now I'm not getting periodic statistics printed to my log file - I use this on a dashboard to visualize metrics. I've built a new server to run the mount and the new server isn't printing the output I am expecting.
Basically the line like the one below is what I'm looking for:
2021/10/13 18:53:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
I currently have the following relative flags set in my mount command:
--syslog
I have also tried DEBUG but that did not resolve the issue.
FWIW I retrieved that sample log from a system I have running rclone v1.57.0 and the system I'm trying to get this log type out of is running v1.58.1. Should I roll back? I haven't tried.
I'm feeding these logs into a splunk server so I'd really prefer not to re-invent the wheel by adding another layer to gathering these stats if possible.
What's your actual full mount command? What version are you running? What's your rclone.conf? Basically, the stuff in the help and support template...
Those logs won’t exist because you are not using any vfs-cache-mode
Was your old mount using it?
Yuka
June 11, 2022, 12:56am
5
See my update.. missed the last line when copy pasting.
I am using full vfs caching.
See version numbers in my first post.
This exact same mount command and conf file on 1.57.x gets me the stats but in 1.58.x does not.
There is no log file to show anything.
By default, polling is once a minute with no limit.
Please post a full debug log as that will show the details we seek.
Yuka
June 11, 2022, 1:14am
7
Where do you see the default polling set to an hour? The documentation you linked me to says the default is once every minute.
Can we get that debug log?
Sample debug log with a small polling interval.
felix@gemini:/opt/rclone/logs$ rclone mount DB: /home/felix/test -vv --vfs-cache-mode full --vfs-cache-poll-interval 10s
2022/06/10 21:52:05 DEBUG : Setting --config "/opt/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/opt/rclone/rclone.conf"
2022/06/10 21:52:05 DEBUG : rclone: Version "v1.58.1" starting with parameters ["rclone" "mount" "DB:" "/home/felix/test" "-vv" "--vfs-cache-mode" "full" "--vfs-cache-poll-interval" "10s"]
2022/06/10 21:52:05 DEBUG : Creating backend with remote "DB:"
2022/06/10 21:52:05 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2022/06/10 21:52:06 DEBUG : vfs cache: root is "/home/felix/.cache/rclone"
2022/06/10 21:52:06 DEBUG : vfs cache: data root is "/home/felix/.cache/rclone/vfs/DB"
2022/06/10 21:52:06 DEBUG : vfs cache: metadata root is "/home/felix/.cache/rclone/vfsMeta/DB"
2022/06/10 21:52:06 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfs/DB/"
2022/06/10 21:52:06 DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfsMeta/DB/"
2022/06/10 21:52:06 DEBUG : Dropbox root '': Mounting on "/home/felix/test"
2022/06/10 21:52:06 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:52:06 DEBUG : : Root:
2022/06/10 21:52:06 DEBUG : : >Root: node=/, err=<nil>
2022/06/10 21:52:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:52:26 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:52:36 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:52:46 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:52:56 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:53:06 DEBUG : Dropbox root '': Checking for changes on remote
2022/06/10 21:53:06 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:53:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2022/06/10 21:53:26 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
Yuka
June 11, 2022, 3:00am
10
Mount command used:
/usr/bin/rclone mount dbox:files /mnt/dbox/files \
--umask=002 \
--gid=1001 \
--uid=0 \
--syslog \
--log-level DEBUG \
--log-systemd \
--vfs-cache-mode full \
--vfs-cache-poll-interval 10s
And here is what is grepped out of syslog (using "grep rclone" as the filter):
Jun 10 21:25:28 dl01 systemd[1]: Started dbox-files.
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : rclone: Version "v1.58.1" starting with parameters ["/usr/bin/rclone" "mount" "dbox:files" "/mnt/dbox/files" "--umask=002" "--gid=1001" "--uid=0" "--syslog" "--log-level" "DEBUG" "--log-systemd" "--vfs-cache-mode" "full" "--vfs-cache-poll-interval" "10s"]
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : rclone: systemd logging support activated
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : Creating backend with remote "dbox:files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : vfs cache: root is "/root/.cache/rclone"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/dbox/files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/dbox/files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/dbox/files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/dbox/files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Mounting on "/mnt/dbox/files"
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : : Root:
Jun 10 21:25:28 dl01 rclone[5509]: <7>DEBUG : : >Root: node=/, err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : /: Lookup: name="test.txt"
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : /: Create: name="test.txt"
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: Open: flags=O_WRONLY|O_CREATE|0x800
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: newRWFileHandle:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): openPending:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: truncate to size=0
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : : Added virtual directory entry vAddFile: "test.txt"
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): >openPending: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: >newRWFileHandle: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : : Added virtual directory entry vAddFile: "test.txt"
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: >Open: fd=test.txt (rw), err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : /: >Create: node=test.txt, handle=&{test.txt (rw)}, err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: Attr:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: Flush:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): RWFileHandle.Flush
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: Setattr: a=Setattr [ID=0xa Node=0x2 Uid=0 Gid=0 Pid=5525] atime=2022-06-10 21:25:40.497198873 -0500 CDT atime=now mtime=2022-06-10 21:25:40.497198873 -0500 CDT mtime=now handle=INVALID-0x0
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: setting modification time to 2022-06-10 21:25:40.497198873 -0500 CDT
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: >Setattr: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: Attr:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: Flush:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): RWFileHandle.Flush
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: >Flush: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: Release:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): RWFileHandle.Release
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): close:
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: setting modification time to 2022-06-10 21:25:40.497198873 -0500 CDT
Jun 10 21:25:40 dl01 rclone[5509]: <6>INFO : test.txt: vfs cache: queuing for upload in 5s
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : test.txt(0xc000b30700): >close: err=<nil>
Jun 10 21:25:40 dl01 rclone[5509]: <7>DEBUG : &{test.txt (rw)}: >Release: err=<nil>
Jun 10 21:25:45 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: starting upload
Jun 10 21:25:46 dl01 rclone[5509]: <7>DEBUG : test.txt: Uploading chunk 1/0
Jun 10 21:25:46 dl01 rclone[5509]: <7>DEBUG : test.txt: Uploading chunk 2/0
Jun 10 21:25:46 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Adding "/files/test.txt" to batch
Jun 10 21:25:47 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Batch idle for 500ms so committing
Jun 10 21:25:47 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Committing sync batch length 1 starting with: /files/test.txt
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Upload batch completed in 154.791694ms
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : Dropbox root 'files': Committed sync batch length 1 starting with: /files/test.txt
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : test.txt: dropbox = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 OK
Jun 10 21:25:48 dl01 rclone[5509]: <6>INFO : test.txt: Copied (new)
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: fingerprint now "0,2022-06-11 02:25:40 +0000 UTC,e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855"
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : test.txt: vfs cache: writeback object to VFS layer
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : test.txt: Not setting pending mod time 2022-06-10 21:25:40.497198873 -0500 CDT as it is already set
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : : Added virtual directory entry vAddFile: "test.txt"
Jun 10 21:25:48 dl01 rclone[5509]: <6>INFO : test.txt: vfs cache: upload succeeded try #1
Jun 10 21:25:48 dl01 rclone[5509]: <7>DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test.txt not removed, freed 0 bytes
Should have had 2 or 3 of the log entries I'm hoping to see.
Seems like your logfile isn't quite right that you are looking at.
felix@gemini:~$ rclone mount DB: /home/felix/test -vv --vfs-cache-mode full --vfs-cache-poll-interval 10s --log-systemd
2022/06/10 23:14:50 DEBUG : Setting --config "/opt/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/opt/rclone/rclone.conf"
<7>DEBUG : rclone: Version "v1.58.1" starting with parameters ["rclone" "mount" "DB:" "/home/felix/test" "-vv" "--vfs-cache-mode" "full" "--vfs-cache-poll-interval" "10s" "--log-systemd"]
<7>DEBUG : rclone: systemd logging support activated
<7>DEBUG : Creating backend with remote "DB:"
<7>DEBUG : Using config file from "/opt/rclone/rclone.conf"
<7>DEBUG : vfs cache: root is "/home/felix/.cache/rclone"
<7>DEBUG : vfs cache: data root is "/home/felix/.cache/rclone/vfs/DB"
<7>DEBUG : vfs cache: metadata root is "/home/felix/.cache/rclone/vfsMeta/DB"
<7>DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfs/DB/"
<7>DEBUG : Creating backend with remote "/home/felix/.cache/rclone/vfsMeta/DB/"
<7>DEBUG : Dropbox root '': Mounting on "/home/felix/test"
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<7>DEBUG : : Root:
<7>DEBUG : : >Root: node=/, err=<nil>
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<7>DEBUG : Dropbox root '': Checking for changes on remote
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
<6>INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
Try just without the logfile and you can see the output live in a terminal or write a log file and share the full log file.
benba
June 11, 2022, 5:56am
12
to filter the systemd log by unit use this;
for example if your service unit has the name rclone
-u for the unit
journalctl -u Rclone -x
system
July 11, 2022, 5:57am
13
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.