Help reading debug logs: which entries refer to vfs writes versus remote writes

Help and Support
1

Goal:
I am looking at creating an automated solution for saving Android application backups directly to an rclone mounted drive with vfs=writes. I need some guidance at interpreting the debug logs.

Workflow:
The oandbackup app takes an Android application (data and akp), bundles it into a compressed, encrypted archive then stores the results. I am exploring the feasibility of configuring the app to backup directly to an rclone remote.

It seems to be working however I am unsure about which file are being written to the vfs versus which files are being written to the remote.

If the intermediate work files (before the final encrypted output) are written to the vfs, uploaded to the remote remote and then deleted, this would not be a good workflow. If however the intermediate files are written to the vfs in memory temporarily then deleted and only the resulting output is uploaded to the remote it would be an ideal (and awesome) rclone application

I have been reading the logs of a test operation and trying to figure out what is being written to the vfs file system and what is being written to the remote.

For example, this seems evident:

  • shared_prefs: Added virtual directory entry vDel: "file.xml"
  • file.xml: vfs cache: removed cache file as file deleted

However, are these lines referring to uploading to the vfs or uploading to the remote?

  • file.xml: vfs cache: queuing for upload in 5s
  • file.log: vfs cache: upload succeeded try #1
  • vfs cache: cancelling writeback (uploading false) 0xb48f87d0 item 71

If file.log: vfs cache: upload succeeded try #1 means it uploaded this file to the remote, when I look I don't see it there. Was it deleted, if so what log line would indicates a file was deleted from a remote?

Is this telling me rclone copied the file to vfs or to the remote:

  • file.xml: Copied (new)

I also see this error commonly, however the end result is that the output looks like it is successfully uploaded, perhaps it tries again?

  • ERROR : path/file.xml: vfs cache: failed to _ensure cache EOF
  • DEBUG : path/file/: vfs cache: failed to _ensure cache EOF is not out of space

I guess I am wondering are all the vfs operations marked with "vfs" or can something like this:
file.xml: Copied (new)

refer to copying files to the vfs or to the remote.

The end result:
This appears to be working. When I look at the remote I see the expected encrypted output of the application, I never see any of the intermediary files. I do not know if they were however uploaded and then deleted afterwards which is what I would like to try to avoid.

Any guidance would be greatly appreciated.

2

If you need --vfs-cache-mode writes for your app to work (rather than --vfs-cache-mode off) then the data will be written to the VFS cache before uploading.

This is uploading to the remote

I would say it should be there... Try a simple copy of a file and see what happens.

Also to the remote

Hmm - I think you are probably running not the latest rclone?

Those INFO level logs are always copying stuff to the remote so look for those. You don't need the debug log for this only -v.

If files are not open and they have been written to then they are eligible for being copied to the remote after

  --vfs-write-back duration                Time to writeback files after last use when using cache. (default 5s)

This log indicates that rclone was uploading a file which was modified so cancelled the upload which is a potential inefficiency.

3

Okay thanks for the detailed response. Unfortunately your answers indicated that all of the log lines that I thought were indicating writing data to VFS were actually writing data to the remote.

This is the opposite of what I was expecting. The end result is that I only see the archive file on the remote. I do not see any of the compressed and bundled files that went into the vfs cache.

I understand I should only look at the INFO level logs to see what is being copied. It seems this is the exact line I am looking for, is this correct?

" upload succeeded try #1"

So assuming those files were indeed uploaded then they most have been deleted afterwards because they do not exist on the remote. Is this a correct assumption? What is the corresponding exact delete log line I should look for to verify this, is it an INFO level log?

4

These are the INFO logs that indicate something was uploaded successfully,eg

2020/11/06 16:11:06 INFO  : FILE.txt: Copied (new)
2020/11/06 16:11:06 INFO  : FILE.txt: vfs cache: upload succeeded try #1

Yes most likely, or the in progress upload will be have been cancelled.

You'll get these logs when it deletes something on the remote

2020/11/06 16:11:22 DEBUG : FILE.txt: Remove:
5

Thank you this is what I needed.

6

So looking at that I often see this:

DEBUG : file.txt: Remove:
INFO : file.txt: vfs cache: removed cache file as file deleted
DEBUG : file.txt: removed metadata from cache as file deleted

Does this indicate that the file was deleted from the remote then deleted from the vfs as well?

Sometimes I see this:
DEBUG : file.txt: Remove:
DEBUG : file.txt: vfs cache: cancelling writeback (uploading false)

This means the file was deleted from the remote then the file was not open but has been written to and is not eligible to be copied again form the vfs?

I see a mix of these lines around every remote: so it would seem to indicate that all of these internediate files are actually being written to the remote and then deleted afterwards which is not the outcome I was hoping for. Would you agree with this assessment?

Is there some way to set a delay between the time the files are in the vfs and the time they are uploaded to the remote?

Thanks for the guidance, this has been very informative.

7

That is the file being removed from the remote and the vfs cache.

This means the file was in the process of being uploaded but the upload was cancelled so the file never actually got to the remote, though it will have used some of the users bandwidth etc.

Yes.

This is controlled by this parameter

  --vfs-write-back duration                Time to writeback files after last use when using cache. (default 5s)

Are there files that you would never want to write back to the remote? Could you identify them by file name? I've had several requests for a feature like that.

8

No I can't identify them by name. I only know that I don't want the original input to be written to the remote. I will look at --vfs-write-back duration. Thanks for the info.

1 Like
9

Just brainstorming...

Maybe a remote control parameter which can set --vfs-write-back-duration would be useful... You could set it to very large when you start then set it to small when you've finished.

10

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