Mounted OneDrive: Invalid Parent Path

TheEpicSnowWolf · December 28, 2022, 11:32am

What is the problem you are having with rclone?

rclone is throwing errors on the mounted OneDrive folder, and I suspect that it causes issues with other services running.

Bit of a background: I am using Nextcloud AIO in a docker instance, which has a version of borg backup included. Using rclone, I have mounted my personal OneDrive with the ‘srv-backup’ folder configured as the root folder (to limit access from the Nextcloud server) to the host as a backup destination. To make this work permanently, I have added the mount command as a systemd service:

[Unit]
Description=Mount OneDrive backup folder via rclone
After=apache2.service

[Service]
ExecStart=/usr/bin/rclone --vfs-cache-mode writes mount onedrive_bkp: /mnt/odr-bkp
ExecStop=/bin/fusermount -u /mnt/odr-bkp
Restart=always

[Install]
WantedBy=default.targ

Now the first time that borg ran on the mounted folder, everything seemed to have worked fine, however I noticed afterwards that it had trouble removing the lock files. Running a backup integrity check also failed, and so did creating a new backup. Looking at systemctl status onedrive-bkp-mount, I can see the following errors:

Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/lock.exclusive
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/lock.exclusive
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data/0
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data/0
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data/0
Dec 28 11:53:47 danserver rclone[1179]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data/0

Now, two things come to mind:

Obviously, I don‘t know whether the errors are related to the backup services failing, but since it is explicitly mentioning the lock files as well as the data directories that it would operate in, I strongly suspect so.
I wonder whether it has something to to with the root directory set to the srv_backup folder in the remote config?

Looking at the rclone code that returns the error messages I get, it seems that it is trying to split the paths /Livefolders/srv_backup/borg/lock.exclusive etc at a :, but clearly this isn‘t possible. I think that‘s a strange error, hence I am filing this as a suspected bug. Also since it seems to occur in the changenotify functionality, it would also explain why it is causing issues when borg is trying to work with existing files, not when it creates new one.

Anyway, bit of a long story here, but hope this context helps! Any help is hugely appreciated.

Run the command 'rclone version' and share the full output of the command.

rclone v1.61.1
- os/version: debian 11.6 (64 bit)
- os/kernel: 5.10.0-20-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.19.4
- go/linking: static
- go/tags: none

Which cloud storage system are you using? (eg Google Drive)

OneDrive

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

n/a

The rclone config contents with secrets removed.

type = onedrive
client_id = <redacted>
client_secret = <redacted>
root_folder_id = <redacted_drive_id>#<redacted_drive_id>!143333
token = {"access_token":"<redacted>","token_type":"Bearer","refresh_token":"<redacted>","expiry":"2022-12-28T12:45:47.583385991+01:00"}
drive_id = <redacted_drive_id>
drive_type = personal

A log from the command with the `-vv` flag

n/a

ncw · December 28, 2022, 11:34pm

Try to reproduce the problem with just rclone if you can. That's way too much extra stuff for me to set up!

Preferably without using rclone mount if possible too.

TheEpicSnowWolf · December 29, 2022, 10:37am

Yeah that is very fair haha, just thought I’d provide the additional context in case something is very obviously wrong with my approach. So I’ve done some tests with just some file service commands on the mounted folder, see output below. (truncated at the service status)

Testing

root@danserver:/mnt# systemctl start onedrive-bkp-mount
root@danserver:/mnt# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
root@danserver:/mnt# cd odr-bkp/
root@danserver:/mnt/odr-bkp# ls
borg
root@danserver:/mnt/odr-bkp# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
root@danserver:/mnt/odr-bkp# mkdir test
root@danserver:/mnt/odr-bkp# ls
borg  test
root@danserver:/mnt/odr-bkp# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
root@danserver:/mnt/odr-bkp# cd test
root@danserver:/mnt/odr-bkp/test# echo 'test' >> test.txt
root@danserver:/mnt/odr-bkp/test# ls
test.txt
root@danserver:/mnt/odr-bkp/test# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
root@danserver:/mnt/odr-bkp/test# cat test.txt
test
root@danserver:/mnt/odr-bkp/test# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/test
root@danserver:/mnt/odr-bkp/test# rm test.txt
root@danserver:/mnt/odr-bkp/test# cd ..
root@danserver:/mnt/odr-bkp# ls
borg  test
root@danserver:/mnt/odr-bkp# rmdir test
root@danserver:/mnt/odr-bkp# systemctl status onedrive-bkp-mount
<…>
Dec 29 11:10:14 danserver systemd[1]: Started Mount OneDrive backup folder via rclone.
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:11:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup
Dec 29 11:12:14 danserver rclone[1002696]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/srv_backup/test

So what it looks like is that the errors indeed appear when read operations are performed on files/folders, however we can also see that the operations do seem to work still (at least those basic commands do). The files and folders are also correctly appearing in OneDrive.

No errors seem to appear when operating directly via rclone commands:

Testing

root@danserver:/mnt# rclone lsd onedrive_bkp: --log-file=log.txt
          -1 2022-12-29 04:01:17         8 borg
root@danserver:/mnt# rclone mkdir onedrive_bkp:/test4 --log-file=log.txt
root@danserver:/mnt# rclone lsd onedrive_bkp: --log-file=log.txt
          -1 2022-12-29 04:01:17         8 borg
          -1 2022-12-29 11:32:10         0 test4
root@danserver:/mnt# rclone touch onedrive_bkp:/test4/test4.txt --log-file=log.txt
root@danserver:/mnt# rclone ls onedrive_bkp:/test4/ --log-file=log.txt
        0 test4.txt
root@danserver:/mnt# rclone cat onedrive_bkp:/test4/test4.txt --log-file=log.txt
root@danserver:/mnt# rclone deletefile onedrive_bkp:/test4/test4.txt --log-file=log.txt
root@danserver:/mnt# rclone ls onedrive_bkp:/test4/ --log-file=log.txt
root@danserver:/mnt# rclone rmdir onedrive_bkp:/test4 --log-file=log.txt
root@danserver:/mnt# rclone lsd onedrive_bkp: --log-file=log.txt
          -1 2022-12-29 04:01:17         8 borg
root@danserver:/mnt# cat log.txt
root@danserver:/mnt#

Ole · December 29, 2022, 11:28am

Hi Dan,

Nice reproductions, I guess Nick will also find it useful to know:

why you have added root_folder_id to your config?
how you determined it?
what happens if you remove it?

TheEpicSnowWolf · December 29, 2022, 12:06pm

Hey Ole,

I am using the root folder id option to limit the access that my server has to OneDrive. Since I am using the remote entirely for the purpose of storing the server backups, I thought it would be good practice to not mount the entire drive, but rather just the backup folder it is supposed to have access to. I retrieved the folder ID through rclone lsf --format “ip” onedrive_bkp: when I originally connected the remote without limiting the root folder.

What I just tried:

Removing the root folder id from the config, and performing some file commands (creating a test folder and test file, cat‘ing it and removing it again), and the errors seem to become less at first, but still appear.
With the root folder id removed, altering the mount command to mount the specific subfolder instead of the full OneDrive share (rclone --vfs-cache-mode writes mount onedrive_bkp:/srv_backup/ /mnt/odr-bkp). Same as above, at first less errors seem to be triggering, but they still very much happen, and when I try to run the backup service, it‘s back to how it was before.

Error messages from linux file commands on “fully mounted” OneDrive

Dec 29 12:52:12 danserver rclone[1078056]: ERROR : test/test2.txt: Failed to copy: Put "https://graph.microsoft.com/v1.0/drives/<redacted>/items/<redacted>:/test2.txt:/content": context canceled
Dec 29 12:52:37 danserver rclone[1078056]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders
Dec 29 12:52:37 danserver rclone[1078056]: ERROR : OneDrive root '': Could not get item full path: invalid parent path: /Livefolders/test

Interestingly, the Failed to Copy error is new, though this might just have been a temporary hickup, didn‘t get that one again.

Error messages from running my backup service again with the modified mount command


ec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/lock>
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data>
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data>
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data>
Dec 29 13:00:14 danserver rclone[1080747]: ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/borg/data>

Ole · December 30, 2022, 12:00pm

Thanks Dan, good to know!

I think we need to simplify as much as possible and then collect a full debug log along with the exact commands executed.

I therefore suggest you start the mount in a terminal using this command:

/usr/bin/rclone mount onedrive_bkp:srv_backup /mnt/odr-bkp --vfs-cache-mode writes -vv --log-format=time,microseconds

where onedrive_bkp doesn't have the root_folder_id in the config.

Next you perform your file commands in another terminal (creating a test folder and test file, cat‘ing it and removing it again). Please space the commands with some seconds to make it easy to correlate the commands with the debug log from the mount.

Stop when you see the first error and kill the mount (using Ctrl-C in the terminal running the mount).

Then post the full output from the terminal running the mount and the corresponding full output from the terminal where you performed the file operations. You may need pastebin or similar for the mount log.

It would of course be great if you can find a way to reproduce the error using just a few well-defined commands, that will make the logs a lot easier to read, and improve chances that we can reproduce/fix any bugs.

TheEpicSnowWolf · January 4, 2023, 7:04am

Hi Ole,

Apologies for the radio silence the past couple of days - I was off for New Year's but back now and finally back at my proper workstation now!

Here's the output from this test. Interestingly, this time the error occured as early as when using the first mkdir command. Do you spot anything from the debug logs?

Commands used

root@danserver:~# cd /mnt/odr-bkp/
root@danserver:/mnt/odr-bkp# mkdir test
root@danserver:/mnt/odr-bkp# cd test
root@danserver:/mnt/odr-bkp/test# echo "test" > testfile.txt
root@danserver:/mnt/odr-bkp/test# cat testfile.txt
test
root@danserver:/mnt/odr-bkp/test# cd ..
root@danserver:/mnt/odr-bkp# rm -rf test

Debug output

dan@danserver:~$ sudo rclone mount onedrive_bkp:srv_backup /mnt/odr-bkp --vfs-cache-mode writes -vv --log-format=time,microseconds
07:49:24.738538 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "mount" "onedrive_bkp:srv_backup" "/mnt/odr-bkp" "--vfs-cache-mode" "writes" "-vv" "--log-format=time,microseconds"]
07:49:24.738782 DEBUG : Creating backend with remote "onedrive_bkp:srv_backup"
07:49:24.738877 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
07:49:25.269970 DEBUG : OneDrive root 'srv_backup': Next delta token is: aTE09NjM4MDgzOTgwNzEzNzM7SUQ9QzAwNEI4RTRBMjgxMDkwMCExMDc7TFI9NjM4MDg0MTE3NjUyNDM7RVA9MjA7U0k9MjI7RExFUD0wO1NHPTE7U089NjtQST0z
07:49:25.270049 DEBUG : vfs cache: root is "/root/.cache/rclone"
07:49:25.270097 DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/onedrive_bkp/srv_backup"
07:49:25.270106 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/onedrive_bkp/srv_backup"
07:49:25.270112 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/onedrive_bkp/srv_backup"
07:49:25.270292 DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/onedrive_bkp/srv_backup"
07:49:25.270856 DEBUG : OneDrive root 'srv_backup': Mounting on "/mnt/odr-bkp"
07:49:25.270983 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
07:49:25.272727 DEBUG : : Root: 
07:49:25.272780 DEBUG : : >Root: node=/, err=<nil>
07:50:25.271106 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
07:50:25.271180 DEBUG : OneDrive root 'srv_backup': Checking for changes on remote
07:50:54.072222 DEBUG : /: Attr: 
07:50:54.072320 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:50:55.456927 DEBUG : /: Attr: 
07:50:55.456965 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:51:11.268389 DEBUG : /: Attr: 
07:51:11.268427 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:51:11.269902 DEBUG : /: Lookup: name="test"
07:51:11.424851 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
07:51:11.425058 DEBUG : /: Mkdir: name="test"
07:51:11.810791 DEBUG : : Added virtual directory entry vAddDir: "test"
07:51:11.810838 DEBUG : /: >Mkdir: node=test/, err=<nil>
07:51:11.810876 DEBUG : test/: Attr: 
07:51:11.810903 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:51:25.270170 DEBUG : OneDrive root 'srv_backup': Checking for changes on remote
07:51:25.271683 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
07:51:25.493716 ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders
07:51:25.493743 ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup
07:51:54.740277 DEBUG : /: Attr: 
07:51:54.740321 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:51:54.740518 DEBUG : test/: Attr: 
07:51:54.740530 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:52:25.270297 DEBUG : OneDrive root 'srv_backup': Checking for changes on remote
07:52:25.271228 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
07:52:51.833381 DEBUG : test/: Lookup: name="testfile.txt"
07:52:52.041379 DEBUG : test/: >Lookup: node=<nil>, err=no such file or directory
07:52:52.041598 DEBUG : test/: Create: name="testfile.txt"
07:52:52.041631 DEBUG : test/testfile.txt: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
07:52:52.041724 DEBUG : test/testfile.txt: newRWFileHandle: 
07:52:52.041751 DEBUG : test/testfile.txt(0xc0002da240): openPending: 
07:52:52.041968 DEBUG : test/testfile.txt: vfs cache: truncate to size=0 (not needed as size correct)
07:52:52.042219 DEBUG : test: Added virtual directory entry vAddFile: "testfile.txt"
07:52:52.042234 DEBUG : test/testfile.txt(0xc0002da240): >openPending: err=<nil>
07:52:52.042376 DEBUG : test/testfile.txt: >newRWFileHandle: err=<nil>
07:52:52.042393 DEBUG : test: Added virtual directory entry vAddFile: "testfile.txt"
07:52:52.042426 DEBUG : test/testfile.txt: >Open: fd=test/testfile.txt (rw), err=<nil>
07:52:52.042459 DEBUG : test/: >Create: node=test/testfile.txt, handle=&{test/testfile.txt (rw)}, err=<nil>
07:52:52.042475 DEBUG : test/testfile.txt: Attr: 
07:52:52.042501 DEBUG : test/testfile.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
07:52:52.042765 DEBUG : &{test/testfile.txt (rw)}: Flush: 
07:52:52.042791 DEBUG : test/testfile.txt(0xc0002da240): RWFileHandle.Flush
07:52:52.042807 DEBUG : &{test/testfile.txt (rw)}: >Flush: err=<nil>
07:52:52.043169 DEBUG : &{test/testfile.txt (rw)}: Write: len=5, offset=0
07:52:52.043191 DEBUG : test/testfile.txt(0xc0002da240): _writeAt: size=5, off=0
07:52:52.043241 DEBUG : test/testfile.txt(0xc0002da240): >_writeAt: n=5, err=<nil>
07:52:52.043268 DEBUG : &{test/testfile.txt (rw)}: >Write: written=5, err=<nil>
07:52:52.043363 DEBUG : &{test/testfile.txt (rw)}: Flush: 
07:52:52.043377 DEBUG : test/testfile.txt(0xc0002da240): RWFileHandle.Flush
07:52:52.043383 DEBUG : &{test/testfile.txt (rw)}: >Flush: err=<nil>
07:52:52.043527 DEBUG : &{test/testfile.txt (rw)}: Release: 
07:52:52.043535 DEBUG : test/testfile.txt(0xc0002da240): RWFileHandle.Release
07:52:52.043542 DEBUG : test/testfile.txt(0xc0002da240): close: 
07:52:52.043769 DEBUG : test/testfile.txt: vfs cache: setting modification time to 2023-01-04 07:52:52.043232206 +0100 CET m=+207.334654180
07:52:52.043793 INFO  : test/testfile.txt: vfs cache: queuing for upload in 5s
07:52:52.043807 DEBUG : test/testfile.txt(0xc0002da240): >close: err=<nil>
07:52:52.043813 DEBUG : &{test/testfile.txt (rw)}: >Release: err=<nil>
07:52:57.044012 DEBUG : test/testfile.txt: vfs cache: starting upload
07:52:57.044359 DEBUG : test/testfile.txt: Starting multipart upload
07:52:57.184010 DEBUG : test/testfile.txt: Uploading segment 0/5 size 5
07:52:57.792082 DEBUG : test/testfile.txt: sha1 = 4e1243bd22c66e76c2ba9eddc1f91394e57f9f83 OK
07:52:57.792115 INFO  : test/testfile.txt: Copied (new)
07:52:57.792147 DEBUG : test/testfile.txt: vfs cache: fingerprint now "5,2023-01-04 06:52:52 +0000 UTC,4e1243bd22c66e76c2ba9eddc1f91394e57f9f83"
07:52:57.792155 DEBUG : test/testfile.txt: vfs cache: writeback object to VFS layer
07:52:57.792165 DEBUG : test: Added virtual directory entry vAddFile: "testfile.txt"
07:52:57.792383 INFO  : test/testfile.txt: vfs cache: upload succeeded try #1
07:53:25.271436 DEBUG : OneDrive root 'srv_backup': Checking for changes on remote
07:53:25.271715 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/testfile.txt not removed, freed 0 bytes
07:53:25.271755 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 5 (was 5)
07:53:25.423197 ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders
07:53:25.423272 ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup
07:53:25.423286 ERROR : OneDrive root 'srv_backup': Could not get item full path: invalid parent path: /Livefolders/srv_backup/test
07:53:35.782947 DEBUG : test/: Attr: 
07:53:35.782992 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:53:35.784299 DEBUG : test/testfile.txt: Open: flags=OpenReadOnly
07:53:35.784315 DEBUG : test/testfile.txt: Open: flags=O_RDONLY
07:53:35.784346 DEBUG : test/testfile.txt: newRWFileHandle: 
07:53:35.784353 DEBUG : test/testfile.txt: >newRWFileHandle: err=<nil>
07:53:35.784358 DEBUG : test/testfile.txt: >Open: fd=test/testfile.txt (rw), err=<nil>
07:53:35.784368 DEBUG : test/testfile.txt: >Open: fh=&{test/testfile.txt (rw)}, err=<nil>
07:53:35.784478 DEBUG : test/testfile.txt: Attr: 
07:53:35.784525 DEBUG : test/testfile.txt: >Attr: a=valid=1s ino=0 size=5 mode=-rw-r--r--, err=<nil>
07:53:35.784625 DEBUG : &{test/testfile.txt (rw)}: Read: len=4096, offset=0
07:53:35.784637 DEBUG : test/testfile.txt(0xc0002da180): _readAt: size=4096, off=0
07:53:35.784653 DEBUG : test/testfile.txt(0xc0002da180): openPending: 
07:53:35.784694 DEBUG : test/testfile.txt: vfs cache: checking remote fingerprint "5,2023-01-04 06:52:52 +0000 UTC,4e1243bd22c66e76c2ba9eddc1f91394e57f9f83" against cached fingerprint "5,2023-01-04 06:52:52 +0000 UTC,4e1243bd22c66e76c2ba9eddc1f91394e57f9f83"
07:53:35.784724 DEBUG : test/testfile.txt: vfs cache: truncate to size=5 (not needed as size correct)
07:53:35.784898 DEBUG : test: Added virtual directory entry vAddFile: "testfile.txt"
07:53:35.784905 DEBUG : test/testfile.txt(0xc0002da180): >openPending: err=<nil>
07:53:35.784922 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true
07:53:35.784941 DEBUG : test/testfile.txt(0xc0002da180): >_readAt: n=5, err=EOF
07:53:35.784960 DEBUG : &{test/testfile.txt (rw)}: >Read: read=5, err=<nil>
07:53:35.785111 DEBUG : &{test/testfile.txt (rw)}: Flush: 
07:53:35.785130 DEBUG : test/testfile.txt(0xc0002da180): RWFileHandle.Flush
07:53:35.785138 DEBUG : &{test/testfile.txt (rw)}: >Flush: err=<nil>
07:53:35.785318 DEBUG : &{test/testfile.txt (rw)}: Release: 
07:53:35.785336 DEBUG : test/testfile.txt(0xc0002da180): RWFileHandle.Release
07:53:35.785342 DEBUG : test/testfile.txt(0xc0002da180): close: 
07:53:35.785622 DEBUG : test/testfile.txt: vfs cache: setting modification time to 2023-01-04 06:52:52 +0000 UTC
07:53:35.785634 DEBUG : test/testfile.txt(0xc0002da180): >close: err=<nil>
07:53:35.785639 DEBUG : &{test/testfile.txt (rw)}: >Release: err=<nil>
07:54:01.709729 DEBUG : /: Attr: 
07:54:01.709762 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:54:01.709856 DEBUG : /: Lookup: name="test"
07:54:01.709868 DEBUG : /: >Lookup: node=test/, err=<nil>
07:54:01.709872 DEBUG : test/: Attr: 
07:54:01.709881 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:54:25.271008 DEBUG : OneDrive root 'srv_backup': Checking for changes on remote
07:54:25.271171 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/testfile.txt not removed, freed 0 bytes
07:54:25.271191 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 5 (was 5)
07:54:39.429504 DEBUG : /: Attr: 
07:54:39.429550 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:54:39.430492 DEBUG : /: Lookup: name="test"
07:54:39.430505 DEBUG : /: >Lookup: node=test/, err=<nil>
07:54:39.430514 DEBUG : test/: Attr: 
07:54:39.430520 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:54:39.430692 DEBUG : test/: ReadDirAll: 
07:54:39.430708 DEBUG : test/: >ReadDirAll: item=3, err=<nil>
07:54:39.430907 DEBUG : test/: Attr: 
07:54:39.430918 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
07:54:39.431014 DEBUG : test/: ReadDirAll: 
07:54:39.431025 DEBUG : test/: >ReadDirAll: item=3, err=<nil>
07:54:39.431139 DEBUG : test/: Lookup: name="testfile.txt"
07:54:39.431149 DEBUG : test/: >Lookup: node=test/testfile.txt, err=<nil>
07:54:39.431157 DEBUG : test/testfile.txt: Attr: 
07:54:39.431167 DEBUG : test/testfile.txt: >Attr: a=valid=1s ino=0 size=5 mode=-rw-r--r--, err=<nil>
07:54:39.431221 DEBUG : test/: Remove: name="testfile.txt"
07:54:39.431229 DEBUG : test/testfile.txt: Remove: 
07:54:39.431356 INFO  : test/testfile.txt: vfs cache: removed cache file as file deleted
07:54:39.431384 DEBUG : test/testfile.txt: vfs cache: removed metadata from cache as file deleted
07:54:39.431390 DEBUG : test: Added virtual directory entry vDel: "testfile.txt"
07:54:39.679198 DEBUG : test/testfile.txt: >Remove: err=<nil>
07:54:39.679239 DEBUG : test/: >Remove: err=<nil>
07:54:39.679482 DEBUG : /: Remove: name="test"
07:54:40.075187 DEBUG : : Added virtual directory entry vDel: "test"
07:54:40.075215 DEBUG : /: >Remove: err=<nil>

Ole · January 4, 2023, 7:55pm

Hi Dan,

No problem, happy New Year!

Perfect test and output, I can confirm that it seems to be an error and your initial guess is spot on:

I tried the same scenario in a debugger, but was unable to reproduce. Still useful though, here is what I learned:

The error is triggered in getItemFullPath being called from changeNotifyRunner each time rclone polls OneDrive for changes.

These are the critical lines added app. 7 months ago by #6134 onedrive: Implement --poll-interval:

github.com

rclone/rclone/blob/98fa93f6d17909e9c6b9778a4dc9e67c58151f6a/backend/onedrive/onedrive.go#L2458-L2463


      
          	if parent := item.GetParentReference(); parent != nil && parent.Path != "" {
          		pathParts := strings.SplitN(parent.Path, ":", 2)
          		if len(pathParts) != 2 {
          			err = fmt.Errorf("invalid parent path: %s", parent.Path)
          			return
          		}

The code will (by default) be executed every minute and I therefore expect you can see the error just by waiting a minute without any activity on the mount.

When I start the mount and wait a minute, the above code executes and parent.Path becomes "/drive/root:", PathParts then becomes ["/drive/root",""] and the error is skipped. All good.

When you start your mount parent.Path becomes "/Livefolders" and PathParts then becomes ["/Livefolders"] and the error is provoked, and things probably start to fall apart.

I guess you see a different parent.Path because you are using an older Microsoft account (from the days OneDrive was called LiveFolders/SkyDrive). Can you confirm? Or is it perhaps a shared drive? or both? or something else?

I cannot (yet) say if the issue is the missing colon or the code assuming a colon. However the fact that you were unable to trigger any issues when using the rclone basic commands makes me suspect a bug in the relatively new code to support OneDrive polling.

I therefore guess you can workaround the issue by disabling the polling by adding --poll-interval=0 to your mount command, it shouldn't make any/much difference if the mount is primarily used to write backups to OneDrive.

TheEpicSnowWolf · January 4, 2023, 11:20pm

Happy New Year to you too Ole, and thank you so much for the analysis! This has brought me a huge step forward toward getting this resolved, at least for my personal use case here.

So first things first, to answer your question, I am honestly not exactly sure how old my Microsoft account is, I know that I started using OneDrive in 2016 which would have been after the SkyDrive rename, but it is not unlikely that my Microsoft account itself is in fact older. Do you know of any quick way to check that? I have not (at least to my knowledge) set up the drive as shared or did anything special to it, should be pretty much just the out-of-the-box OneDrive that every personal M365 subscriber gets.

Now, adding --poll-interval=0 to the mount command has actually resolved the errors, and this confirmed that these were actually responsible for the backup issues as well - at least for some of them, it seems. Now, to give a bit more context again, borg backup is essentially creating a "lock" folder during its operations to indicate that the backup repository is busy. It is meant to delete this automatically once done. In the past, I had received the rclone full path errors that we were discussing here so far which apparently resulted in borg not able to handle the locks properly, but I was always able to delete the folder manually via a classic rm -rf to make the backup start again, before it failed as it ran into the same error.

So, the good news is, after removing the lock this time and trying to run a backup with the poll intervall set to 0, I actually got a backup to complete successfully, which is amazing! However, when borg tried to clean up the repository by removing the lock, it ran into an I/O error, which is at least a new one.

Excerpt from the borg logs

Backup finished successfully on 04.01.2023 - 22:53:28 (00 hours 00 minutes 57 seconds)
Failed to remove lock dir: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'
Failed to remove lock dir: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'
Failed to remove lock dir: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'
Failed to remove lock dir: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'
Failed to remove lock dir: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'
Exception ignored in: <function Repository.__del__ at 0x7fc7a4f10550>
Traceback (most recent call last):
   <...>
borg.locking.LockTimeout: Failed to create/acquire the lock /mnt/borgbackup/borg/lock.exclusive (timeout).
Local Exception
Traceback (most recent call last):
   <...>
OSError: [Errno 5] Input/output error: '/mnt/borgbackup/borg/lock.exclusive'

(note that the "Failed to create/acquire the lock" is the same error that I had before, just that this time it seems that it's caused by a different issue?)

rclone error logs

Jan 04 23:53:38 danserver rclone[3248475]: ERROR : IO error: directory not empty
Jan 04 23:53:38 danserver rclone[3248475]: ERROR : borg/lock.exclusive.48e2uze5.tmp: Dir.Rename error: can't copy directory - destination already exists
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : borg/lock.exclusive/: Dir.Remove failed to remove directory: directory not empty
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : IO error: directory not empty
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : borg/lock.exclusive.48e2uze5.tmp: Dir.Rename error: can't copy directory - destination already exists
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : borg/lock.exclusive/: Dir.Remove failed to remove directory: directory not empty
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : IO error: directory not empty
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : borg/lock.exclusive.48e2uze5.tmp: Dir.Rename error: can't copy directory - destination already exists
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : borg/lock.exclusive/: Dir.Remove failed to remove directory: directory not empty
Jan 04 23:53:39 danserver rclone[3248475]: ERROR : IO error: directory not empty

Now, I was almost willing to blame that on some issue with borg, however when I then tried to remove the lock directory manually, I got the same error:

Linux commands

dan@danserver:~$ sudo rm -rf /mnt/odr-bkp/borg/lock.exclusive
rm: cannot remove '/mnt/odr-bkp/borg/lock.exclusive': Input/output error

rclone logs

Jan 04 23:56:07 danserver rclone[3248475]: ERROR : borg/lock.exclusive/: Dir.Remove failed to remove directory: directory not empty
Jan 04 23:56:07 danserver rclone[3248475]: ERROR : IO error: directory not empty

I am especially surprised since a non-empty directory shouldn't be an issue for with the -rf flag, so I wonder what is causing this. Worth noting that, eventually, the command worked again and I was able to remove the directory, but I wonder if this is some sort of limitation the poll interval has introduced?

Ole · January 5, 2023, 9:10am

Your are welcome, happy to hear!

Thanks, sounds like something rclone should be able to handle without issues. The OneDrive backend was added to rclone in 2015, so I would expect it has handled lots of old Microsoft accounts before.

This just further strengthens my suspicion that the bug lies in the relatively new polling code.

Great, can I persuade you to create a GitHub bug report based on the information in your above post:
https://forum.rclone.org/t/mounted-onedrive-invalid-parent-path/35106/7

Hmm, not sure, but it looks like a timing issue where the underlying rclone rmdir sometimes reaches OneDrive before the rclone deletefiles have completed. Perhaps triggered by Borg doing rapid renames/deletes of temp files.

I did some research and it seems like Borg and rclone mount doesn't always play well together, here are some links:
https://forum.rclone.org/t/best-practice-for-integrating-rclone-and-borgbackup/26166
https://github.com/borgbackup/borg/issues/5324

Based on the pattern I see in your logs, it may be possible to work around (some of) these issues by keeping more data in the local mount cache and writing less often to OneDrive. Here are some parameters you may want to modify/add to your mount command to do this:

--vfs-cache-mode=full --vfs-write-back=10m --vfs-cache-max-age=48h --vfs-cache-max-size=10G

You can probably guess my intent when reading about the parameters here:
https://rclone.org/commands/rclone_mount/#vfs-file-caching

It is a quick guess based on incomplete knowledge and therefore probably need some testing and adjustments to fit your machine and usage - and is given without any guarantee of success

TheEpicSnowWolf · January 5, 2023, 10:00pm

Absolutely, will create the issue on GitHub in a second (done: Mounted OneDrive - Invalid Parent Path '/Livefolders' · Issue #6669 · rclone/rclone · GitHub)!

Thank you also for the pointers on the other discussions about rclone and borg. In the long term, I might need to consider ditching the integrated borg functionality in Nextcloud for something "external" so that I can use restic for the sake of compatibility/stability, but for now I'm super excited to report that with the cache adjustments you suggested, I finally got a backup to complete from start to finish without any issues!

This is my mount command:

/usr/bin/rclone --poll-interval=0 --vfs-cache-mode=full --vfs-write-back=5m --vfs-cache-max-age=6h mount onedrive_bkp:srv_backup /mnt/odr-bkp

I've lowered the write back time as well as the max age for now, and not included the maximum size (as I'm happy to sacrifice disk space for the backup cache if it means letting it run more stable), and will observe this for a while to see whether it needs adjustments, but for now it seems to be working - backup completed, no errors in rclone and no lock files left. If I'm getting a notification tomorrow morning that my scheduled nightly backup ran successfully, I'm a happy man.

Thanks so much for your patience and help with all of this Ole - really appreciate it!

Ole · January 6, 2023, 9:12am

Thanks, you are welcome Dan!

Happy to hear the backup completed successfully

system · February 5, 2023, 9:12am

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