OneDrive mount mkdir extermely slow

fuser · February 26, 2023, 11:00pm

What is the problem you are having with rclone?

Rclone is fast on creating files but extremly slow creating and removing directories on OneDrive. It takes up to 15s to create or delete an empty directory.

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

- os/version: debian 11.6 (64 bit)
- os/kernel: 6.0.0-0.deb11.6-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.19.4
- go/linking: static
- go/tags: none

Are you on the latest version of rclone? You can validate by checking the version listed here: Rclone downloads
--> yes

Which cloud storage system are you using?

OneDrive

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

backupper@nuc1:~/restic$ time touch test ; time rm  test

real	0m0,006s
user	0m0,002s
sys	0m0,001s

real	0m0,001s
user	0m0,001s
sys	0m0,000s

backupper@nuc1:~/restic$ time mkdir test ; time rm -r test

real	0m13,102s
user	0m0,003s
sys	0m0,001s

real	0m22,045s
user	0m0,000s
sys	0m0,004s

The rclone config contents with secrets removed.

[OneDrive]
type = onedrive
token = {"access_token":"1234">
drive_id = "mydrive"
drive_type = personal

rclone mount \
--daemon \
--umask=022 \
--allow-other \
--timeout=1h \
--poll-interval=15s \
--dir-cache-time=120m \
--cache-dir=$HOME/rclone/cache/restic \
--vfs-cache-mode=full \
--vfs-cache-max-size=200G \
--vfs-cache-max-age=12h \
--vfs-cache-poll-interval 5m \
--vfs-read-ahead 1M  \
--log-file=$HOME/rclone_mounts/rclone.log \
--log-level DEBUG \
OneDrive:restic $HOME/rclone_mounts/restic

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

2023/02/26 23:52:24 DEBUG : /: Remove: name="test"
2023/02/26 23:52:24 DEBUG : test: Remove:
2023/02/26 23:52:24 DEBUG : test: vfs cache: cancelling writeback (uploading false) 0xc0003e6a80 item 1
2023/02/26 23:52:24 INFO  : test: vfs cache: removed cache file as file deleted
2023/02/26 23:52:24 DEBUG : test: vfs cache: removed metadata from cache as file deleted
2023/02/26 23:52:24 DEBUG : : Added virtual directory entry vDel: "test"
2023/02/26 23:52:24 DEBUG : test: >Remove: err=<nil>
2023/02/26 23:52:24 DEBUG : /: >Remove: err=<nil>
2023/02/26 23:52:26 DEBUG : OneDrive root 'restic': Checking for changes on remote
2023/02/26 23:52:40 DEBUG : /: Lookup: name="test"
2023/02/26 23:52:40 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2023/02/26 23:52:40 DEBUG : /: Create: name="test"
2023/02/26 23:52:40 DEBUG : test: Open: flags=O_WRONLY|O_CREATE|0x800
2023/02/26 23:52:40 DEBUG : test: newRWFileHandle:
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): openPending:
2023/02/26 23:52:40 DEBUG : test: vfs cache: truncate to size=0 (not needed as size correct)
2023/02/26 23:52:40 DEBUG : : Added virtual directory entry vAddFile: "test"
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): >openPending: err=<nil>
2023/02/26 23:52:40 DEBUG : test: >newRWFileHandle: err=<nil>
2023/02/26 23:52:40 DEBUG : : Added virtual directory entry vAddFile: "test"
2023/02/26 23:52:40 DEBUG : test: >Open: fd=test (rw), err=<nil>
2023/02/26 23:52:40 DEBUG : /: >Create: node=test, handle=&{test (rw)}, err=<nil>
2023/02/26 23:52:40 DEBUG : test: Attr:
2023/02/26 23:52:40 DEBUG : test: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/02/26 23:52:40 DEBUG : &{test (rw)}: Flush:
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): RWFileHandle.Flush
2023/02/26 23:52:40 DEBUG : &{test (rw)}: >Flush: err=<nil>
2023/02/26 23:52:40 DEBUG : test: Setattr: a=Setattr [ID=0x20 Node=0x2 Uid=1001 Gid=100 Pid=9208] atime=2023-02-26 23:52:40.82474395 +0100 CET atime=now mtime=2023-02->
2023/02/26 23:52:40 DEBUG : test: vfs cache: setting modification time to 2023-02-26 23:52:40.82474395 +0100 CET
2023/02/26 23:52:40 DEBUG : test: >Setattr: err=<nil>
2023/02/26 23:52:40 DEBUG : test: Attr:
2023/02/26 23:52:40 DEBUG : test: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/02/26 23:52:40 DEBUG : &{test (rw)}: Flush:
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): RWFileHandle.Flush
2023/02/26 23:52:40 DEBUG : &{test (rw)}: >Flush: err=<nil>
2023/02/26 23:52:40 DEBUG : &{test (rw)}: Release:
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): RWFileHandle.Release
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): close:
2023/02/26 23:52:40 DEBUG : test: vfs cache: setting modification time to 2023-02-26 23:52:40.82474395 +0100 CET
2023/02/26 23:52:40 INFO  : test: vfs cache: queuing for upload in 5s
2023/02/26 23:52:40 DEBUG : test(0xc000bfb900): >close: err=<nil>
2023/02/26 23:52:40 DEBUG : &{test (rw)}: >Release: err=<nil>
2023/02/26 23:52:40 DEBUG : /: Remove: name="test"
2023/02/26 23:52:40 DEBUG : test: Remove:
2023/02/26 23:52:40 DEBUG : test: vfs cache: cancelling writeback (uploading false) 0xc00061d810 item 2
2023/02/26 23:52:40 INFO  : test: vfs cache: removed cache file as file deleted
2023/02/26 23:52:40 DEBUG : test: vfs cache: removed metadata from cache as file deleted
2023/02/26 23:52:40 DEBUG : : Added virtual directory entry vDel: "test"
2023/02/26 23:52:40 DEBUG : test: >Remove: err=<nil>
2023/02/26 23:52:40 DEBUG : /: >Remove: err=<nil>
2023/02/26 23:52:41 DEBUG : OneDrive root 'restic': Checking for changes on remote
2023/02/26 23:52:43 DEBUG : /: Lookup: name="test"
2023/02/26 23:52:43 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2023/02/26 23:52:43 DEBUG : /: Mkdir: name="test"
2023/02/26 23:52:56 DEBUG : OneDrive root 'restic': Checking for changes on remote
2023/02/26 23:52:57 DEBUG : : Added virtual directory entry vAddDir: "test"
2023/02/26 23:52:57 DEBUG : /: >Mkdir: node=test/, err=<nil>
2023/02/26 23:52:57 DEBUG : test/: Attr:
2023/02/26 23:52:57 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/02/26 23:52:57 DEBUG : test/: ReadDirAll:
2023/02/26 23:53:04 DEBUG : test/: >ReadDirAll: item=2, err=<nil>
2023/02/26 23:53:04 DEBUG : test/: Attr:
2023/02/26 23:53:04 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/02/26 23:53:04 DEBUG : /: Remove: name="test"
2023/02/26 23:53:04 DEBUG : : changeNotify: relativePath="test", type=0
2023/02/26 23:53:04 DEBUG : : invalidating directory cache
2023/02/26 23:53:04 DEBUG : test: invalidating directory cache
2023/02/26 23:53:04 DEBUG : : >changeNotify:
2023/02/26 23:53:11 DEBUG : OneDrive root 'restic': Checking for changes on remote
2023/02/26 23:53:19 DEBUG : : Added virtual directory entry vDel: "test"
2023/02/26 23:53:19 DEBUG : /: >Remove: err=<nil>

ncw · February 27, 2023, 10:11am

If you use rmdir to remove the empty directory, it will run much quicker. I only see 2.3s for rm -r emptydir here though.

I note your mount is called restic - rclone is much more efficient used with restic using the integration here than using a mount.

fuser · February 27, 2023, 3:10pm

The supposed restic setup does not work for me because the intended setup is to run rclone on a server and restic on clients which backup to the server with sftp:backup@server:restic/clientrepo as archive addresses.

Anyway, deletion is not the major issue, this happens rarely enough, but creating and navigating the directory tree is equally slow.

Initializing a Restic repo in a Rclone mounted drive takes more than 2 hours because Restic creates 250+ empty directories in this process. This happens even when started on the server directly.

Copying the mostly empty directory tree from a local drive to the Rclone mount take likewise 2h+.

When I "cd" and "ls" through the mounted Rclone direcories it is very slow, ls can take 10-15s as well. So it is not only a Restic issue.

It just seems caching the directories is not working at all. Intended, wrong config or bug?

ncw · February 27, 2023, 3:38pm

That is very slow....

If you copy the tree with rclone copy --create-empty-src-dirs does that work quicker?

Rclone will be accessing the source to see whether the directories still exist.

I don't know why it is so slow. Onedrive is known for being slow though. If you search the forum you'll find lots of threads about it and some tips on how to speed it up.

We can see if @Ole has time to help too.

fuser · February 27, 2023, 4:31pm

Just because the info is missing up where it belongs: I using version rclone v1.61.1

Ole · February 27, 2023, 4:44pm

Hi fuser,

It looks like you are testing from one of your clients.

Do you see the same if performing the test directly on the server? That is something like:

ResticServer/someuser:/.../rclone_mounts/restic$ time mkdir testdir ; time rm -r testdir

If your still see the issue, do you then see the same if testing directly againt the OneDrive remote without using the rclone mount? That is something like:

time rclone mkdir OneDrive:restic/testdir2; time rclone rmdir OneDrive:restic/testdir2

fuser · February 27, 2023, 9:05pm

I was testing directly from the server. The restic issue only came up because the directories are named "restic" for obvious resons.

What I did:

Ran "restic init" on the server on the Rclone mount. Restic creates some 250 empty directories and a total 1.1 MB of Data in this process, took 2.5h
Ran "restic init" on the server on the harddisk, took 7 seconds as expected.
Moved the mostly empty directory tree from step 2 into the Rclone mount using "mv" command. Took again 2.5h
Initializing from the client takes about the same amount of time.

I just made a initial backup now from the client with 300GB of data which coincidently took as well 2,5h, but this is as expected. File creation inside the exiting directories is sufficiently fast. I'll wait for tomorrow for the syncing completed before making further investigations.

The thing I am suspicious of if there is any network issue, not in the throughput, but rather in the latency. Is there any way to find out which server/ip address Rclone is contacting for OneDrive?

Ole · February 28, 2023, 7:42am

I would like rule out some of the more frequently seen issues first such as

a local issue on your machine
an issue with the rclone mount settings (or a limitation/bug in the rclone mount code)
OneDrive rate limits (throttling)

To do this I would like to collect some additional information to understand your situation better.

How many folders and files are created by "restic init"?

You can use rclone to count folders like this:

rclone lsf -R --dirs-only /some/folder | wc -l

and files like this:

rclone lsf -R --files-only /some/folder | wc -l

and then I need you to do this (to see if the long response times are related to OneDrive or your mount/machine):

Ole:

do you then see the same if testing directly againt the OneDrive remote without using the rclone mount? That is something like:
time rclone mkdir OneDrive:restic/testdir2; time rclone rmdir OneDrive:restic/testdir2

fuser · March 1, 2023, 12:11pm

As said Restic creates about 260 folders during initialization. It creates a "data" folder with 256 directories "00" through "ff" in preparation for the backup files. Nothing wrong with that.

So the runtime surely comes from the directory creation. I have the same effect when using "mv" into the Rclone mount., so it is not Restic related.

(The 7 seconds in took on the harddisk actually include entering the password twice)

ncw · March 1, 2023, 12:15pm

This is how long directory creation takes for me

Onedrive personal

$ time rclone mkdir onedrive:testdir  ; time rclone rmdir onedrive:testdir 

real	0m1.511s
user	0m0.178s
sys	0m0.028s

real	0m0.774s
user	0m0.160s
sys	0m0.034s

Onedrive business

$ time rclone mkdir onedriveb:testdir  ; time rclone rmdir onedriveb:testdir 

real	0m2.307s
user	0m0.165s
sys	0m0.035s

real	0m1.946s
user	0m0.174s
sys	0m0.020s

How long do those tests take for you @fuser

fuser · March 10, 2023, 10:06am

As can be seen in my initial posting: Creation took 13s and deletion 22s.

ncw · March 10, 2023, 10:09am

Can you do those tests not through the mount - that is what I'm asking rclone mount is very complicated so if we can take it out of the equation it is one less thing to debug.

If the rclone mkdir is slow, then run it with -vv --dump bodies and you'll be able to see exactly what rclone is sending to the host. You might want to run with --log-format time,microseconds also for more accurate timing.

fuser · March 12, 2023, 4:18pm

time rclone -vv --dump bodies mkdir OneDrive:testdir 2> rclone.log

real    0m10,233s
user    0m0,095s
sys     0m0,041s

The resulting rclone.log shows a gap between 17:07:37 and 17:07:42

2023/03/12 17:07:34 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "-vv" "--dump" "bodies" "mkdir" "OneDrive:testdir"]
2023/03/12 17:07:34 DEBUG : Creating backend with remote "OneDrive:testdir"
2023/03/12 17:07:34 DEBUG : Using config file from "/srv/dev-disk-by-uuid-5a704a5f-6440-4c0e-9d77-f0bb248d7f9b/home/backupper/.config/rclone/rclone.conf"
2023/03/12 17:07:34 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2023/03/12 17:07:34 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:34 DEBUG : HTTP REQUEST (req 0xc00087a600)
2023/03/12 17:07:34 DEBUG : GET /v1.0/drives/f8aa10bd0a4f3604/root HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/12 17:07:34 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:42 DEBUG : HTTP RESPONSE (req 0xc00087a600)
2023/03/12 17:07:42 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: private
Client-Request-Id: 9a81c5a0-daf0-4879-a88c-3c2b65d7a153
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Sun, 12 Mar 2023 16:07:41 GMT
Odata-Version: 4.0
Request-Id: 9a81c5a0-daf0-4879-a88c-3c2b65d7a153
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"000","RoleInstance":"AM1PEPF000105A5"}}

3f9
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#drives('f8aa10bd0a4f3604')/root/$entity","createdDateTime":"2021-02-28T14:44:43.777Z","cTag":"adDpGOEFBMTBCRDBBNEYzNjA0ITEwMS42MzgxNDIzNDA0NDcyMDAwMDA","eTag":"aRjhBQTEwQkQwQTRGMzYwNCExMDEuMA","id":"F8AA10BD0A4F3604!101","lastModifiedDateTime":"2023-03-12T16:07:24.72Z","name":"root","size":425189307676,"webUrl":"https://onedrive.live.com/?cid=f8aa10bd0a4f3604","createdBy":{"application":{"displayName":"OneDrive website","id":"44048800"},"user":{"displayName":"Michael Heidecker","id":"f8aa10bd0a4f3604"}},"lastModifiedBy":{"application":{"displayName":"OneDrive website","id":"44048800"},"user":{"displayName":"Michael Heidecker","id":"f8aa10bd0a4f3604"}},"parentReference":{"driveId":"f8aa10bd0a4f3604","driveType":"personal"},"fileSystemInfo":{"createdDateTime":"2021-02-28T14:44:43.776Z","lastModifiedDateTime":"2021-02-28T14:44:43.776Z"},"folder":{"childCount":7,"view":{"viewType":"thumbnails","sortBy":"name","sortOrder":"ascending"}},"root":{}}
0

2023/03/12 17:07:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:42 DEBUG : HTTP REQUEST (req 0xc0005c5300)
2023/03/12 17:07:42 DEBUG : GET /v1.0/drives/f8aa10bd0a4f3604/items/F8AA10BD0A4F3604!101:/testdir: HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/12 17:07:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:42 DEBUG : HTTP RESPONSE (req 0xc0005c5300)
2023/03/12 17:07:42 DEBUG : HTTP/1.1 404 Not Found
Transfer-Encoding: chunked
Client-Request-Id: ae802830-a7d3-4fa5-b992-e181324ec4a9
Content-Type: application/json
Date: Sun, 12 Mar 2023 16:07:42 GMT
Request-Id: ae802830-a7d3-4fa5-b992-e181324ec4a9
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"000","RoleInstance":"AM1PEPF000105A5"}}

dc
{"error":{"code":"itemNotFound","message":"Item does not exist","innerError":{"date":"2023-03-12T16:07:42","request-id":"ae802830-a7d3-4fa5-b992-e181324ec4a9","client-request-id":"ae802830-a7d3-4fa5-b992-e181324ec4a9"}}}
0

2023/03/12 17:07:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:42 DEBUG : HTTP REQUEST (req 0xc00087a400)
2023/03/12 17:07:42 DEBUG : GET /v1.0/drives/f8aa10bd0a4f3604/items/F8AA10BD0A4F3604!101:/testdir HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/12 17:07:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:43 DEBUG : HTTP RESPONSE (req 0xc00087a400)
2023/03/12 17:07:43 DEBUG : HTTP/1.1 404 Not Found
Transfer-Encoding: chunked
Client-Request-Id: b08e8b8b-e867-4f8e-8ec5-bafa77795fec
Content-Type: application/json
Date: Sun, 12 Mar 2023 16:07:42 GMT
Request-Id: b08e8b8b-e867-4f8e-8ec5-bafa77795fec
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"000","RoleInstance":"AM1PEPF000105A5"}}

dc
{"error":{"code":"itemNotFound","message":"Item does not exist","innerError":{"date":"2023-03-12T16:07:43","request-id":"b08e8b8b-e867-4f8e-8ec5-bafa77795fec","client-request-id":"b08e8b8b-e867-4f8e-8ec5-bafa77795fec"}}}
0

2023/03/12 17:07:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:43 DEBUG : OneDrive root 'testdir': Making directory
2023/03/12 17:07:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:43 DEBUG : HTTP REQUEST (req 0xc0007dac00)
2023/03/12 17:07:43 DEBUG : GET /v1.0/drives/f8aa10bd0a4f3604/items/F8AA10BD0A4F3604!101:/testdir: HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/12 17:07:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:44 DEBUG : HTTP RESPONSE (req 0xc0007dac00)
2023/03/12 17:07:44 DEBUG : HTTP/1.1 404 Not Found
Transfer-Encoding: chunked
Client-Request-Id: 3df4e9b7-7a1f-45d1-ad86-a74ff10548ac
Content-Type: application/json
Date: Sun, 12 Mar 2023 16:07:43 GMT
Request-Id: 3df4e9b7-7a1f-45d1-ad86-a74ff10548ac
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"000","RoleInstance":"AM1PEPF000105A5"}}

dc
{"error":{"code":"itemNotFound","message":"Item does not exist","innerError":{"date":"2023-03-12T16:07:44","request-id":"3df4e9b7-7a1f-45d1-ad86-a74ff10548ac","client-request-id":"3df4e9b7-7a1f-45d1-ad86-a74ff10548ac"}}}
0

2023/03/12 17:07:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:44 DEBUG : HTTP REQUEST (req 0xc00087ac00)
2023/03/12 17:07:44 DEBUG : POST /v1.0/drives/f8aa10bd0a4f3604/items/F8AA10BD0A4F3604!101/children HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Content-Length: 76
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"name":"testdir","folder":{"childCount":0},"@name.conflictBehavior":"fail"}
2023/03/12 17:07:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:07:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:44 DEBUG : HTTP RESPONSE (req 0xc00087ac00)
2023/03/12 17:07:44 DEBUG : HTTP/1.1 201 Created
Transfer-Encoding: chunked
Cache-Control: no-store
Client-Request-Id: 23c23852-50f1-480f-9704-47e62d043b70
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Sun, 12 Mar 2023 16:07:43 GMT
Location: https://s2s-api.onedrive.com/v1.0/drives('f8aa10bd0a4f3604')/items('F8AA10BD0A4F3604!101')/children('F8AA10BD0A4F3604!198775')
Odata-Version: 4.0
Request-Id: 23c23852-50f1-480f-9704-47e62d043b70
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"000","RoleInstance":"AM1PEPF000105A5"}}

42a
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#drives('f8aa10bd0a4f3604')/items('F8AA10BD0A4F3604%21101')/children/$entity","createdDateTime":"2023-03-12T16:07:44.597Z","cTag":"adDpGOEFBMTBCRDBBNEYzNjA0ITE5ODc3NS42MzgxNDIzNDA2NDU5NzAwMDA","eTag":"aRjhBQTEwQkQwQTRGMzYwNCExOTg3NzUuMA","id":"F8AA10BD0A4F3604!198775","lastModifiedDateTime":"2023-03-12T16:07:44.597Z","name":"testdir","size":0,"webUrl":"https://1drv.ms/f/s!AAQ2Twq9EKr4jJB3","createdBy":{"application":{"displayName":"rclone","id":"48211038"},"user":{"displayName":"Michael Heidecker","id":"f8aa10bd0a4f3604"}},"lastModifiedBy":{"application":{"displayName":"rclone","id":"48211038"},"user":{"displayName":"Michael Heidecker","id":"f8aa10bd0a4f3604"}},"parentReference":{"driveId":"f8aa10bd0a4f3604","driveType":"personal","id":"F8AA10BD0A4F3604!101","path":"/drive/root:"},"fileSystemInfo":{"createdDateTime":"2023-03-12T16:07:44.596Z","lastModifiedDateTime":"2023-03-12T16:07:44.596Z"},"folder":{"childCount":0,"view":{"viewType":"thumbnails","sortBy":"name","sortOrder":"ascending"}}}
0

2023/03/12 17:07:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:07:44 DEBUG : 5 go routines active

time rclone -vv --dump bodies rmdir OneDrive:testdir 2> rclone.log

real    0m9,024s
user    0m0,091s
sys     0m0,024s

Here ist the gap between 17:16:26 and 17:16:34

2023/03/12 17:16:26 DEBUG : rclone: Version "v1.61.1" starting with parameters ["rclone" "-vv" "--dump" "bodies" "rmdir" "OneDrive:testdir"]
2023/03/12 17:16:26 DEBUG : Creating backend with remote "OneDrive:testdir"
2023/03/12 17:16:26 DEBUG : Using config file from "/srv/dev-disk-by-uuid-5a704a5f-6440-4c0e-9d77-f0bb248d7f9b/home/backupper/.config/rclone/rclone.conf"
2023/03/12 17:16:26 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2023/03/12 17:16:26 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:16:26 DEBUG : HTTP REQUEST (req 0xc000267e00)
2023/03/12 17:16:26 DEBUG : GET /v1.0/drives/f8aa10bd0a4f3604/root HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/12 17:16:26 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/12 17:16:34 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/12 17:16:34 DEBUG : HTTP RESPONSE (req 0xc000267e00)
2023/03/12 17:16:34 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: private
Client-Request-Id: bbf9657e-a2c6-4f9a-9bdf-9ace3d82af33
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Sun, 12 Mar 2023 16:16:33 GMT
Odata-Version: 4.0
Request-Id: bbf9657e-a2c6-4f9a-9bdf-9ace3d82af33
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"005","RoleInstance":"AM4PEPF00015148"}}

<snip>

ncw · March 13, 2023, 10:18am

That is when rclone is listing your root directory I think.

The actual mkdir appears to take no time at all.

This is the same - this is a list of the root directory taking all the time.

Do you have a lot of items in your root directory?

Ole · March 15, 2023, 8:30am

Looks very weird to me, and certainly outside my area of expertise.

Not OneDrive API expert, but the request only seems to be requesting meta data for the OneDrive root.

No idea why this can take so long when the rest of the responses are (relatively) quick.

Agree.

Apparently not according to this snip from the response (req 0xc00087a600):

My best guess is therefore that something is delaying the transmission of the very first request to OneDrive.

Could be the initial DNS lookup, a proxy, firewall, IPv4/IPv6 issues, etc. etc.

@fuser What do you see if you try this:

time ping -c 1 onedrive.microsoft.com

fuser · March 15, 2023, 9:49pm

Could be the initial DNS lookup,

This seemed to be the problem!

My Rclone was running on a server (192.168.1.11) which hosts as well a pihole dns running inside a docker container (192.168.1.4). The DHCP on the router distributed the pihole address as DNS in the network. But Docker does not route traffic from the host to the container, so a ping from the server to the DNS 192.168.1.4 failed. Apparently Rclones DNS lookup tried to contact 192.168.1.4 first, got a timeout, and then fell back to DNS 8.8.8.8 after a few seconds.

So I set up my DHCP server to provide 8.8.8.8 as a primary DNS for my server only and voilà, a "Restic init" takes only 5 minutes instead of 2 hours.

Thanks a lot for pointing me in the correct direction even id not an Rclone problem!

Ole · March 16, 2023, 8:13am

You are welcome, happy to hear

ncw · March 16, 2023, 9:14am

I keep meaning to buy the "it was DNS" t-shirt! Well done @Ole for suggesting it.

system · March 19, 2023, 9:14am

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