Union of oneDrive for business upstreams: Getting object not found error

ctrl-q · March 18, 2023, 9:23pm

What is the problem you are having with rclone?

Getting object not found when copying a file to a union backend with both upstreams being on OneDrive for Business

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

rclone v1.61.1

os/version: arch (64 bit)
os/kernel: 6.2.6-arch1-1 (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.19.4
go/linking: dynamic
go/tags: none

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

OneDrive for Business

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

touch x
rclone copy x u:

The rclone config contents with secrets removed.

[main]
type = onedrive
token = <redacted>
drive_id = <redacted>
drive_type = business

[u]
type = union
upstreams = main: main:/xyz

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

2023/03/18 17:19:54 DEBUG : rclone: Version "v1.61.1" starting with parameters ["/usr/bin/rclone" "copy" "x" "u:" "-vv" "--log-file" "/tmp/x.log"]
2023/03/18 17:19:54 DEBUG : Creating backend with remote "x"
2023/03/18 17:19:54 DEBUG : Using config file from "/tmp/rclone.conf"
2023/03/18 17:19:54 DEBUG : fs cache: adding new entry for parent of "x", "/home/owner"
2023/03/18 17:19:54 DEBUG : Creating backend with remote "u:"
2023/03/18 17:19:54 DEBUG : Creating backend with remote "main:/xyz"
2023/03/18 17:19:54 DEBUG : Creating backend with remote "main:"
2023/03/18 17:19:54 DEBUG : fs cache: renaming cache item "main:/xyz" to be canonical "main:xyz"
2023/03/18 17:19:54 DEBUG : fs cache: switching user supplied name "main:/xyz" for canonical name "main:xyz"
2023/03/18 17:19:54 DEBUG : union root '': actionPolicy = *policy.EpAll, createPolicy = *policy.EpMfs, searchPolicy = *policy.FF
2023/03/18 17:19:55 DEBUG : x: Need to transfer - File not found at Destination
2023/03/18 17:19:57 ERROR : x: Failed to copy: object not found
2023/03/18 17:19:57 ERROR : Attempt 1/3 failed with 1 errors and: object not found
2023/03/18 17:19:57 DEBUG : x: Need to transfer - File not found at Destination
2023/03/18 17:19:58 ERROR : x: Failed to copy: object not found
2023/03/18 17:19:58 ERROR : Attempt 2/3 failed with 1 errors and: object not found
2023/03/18 17:19:59 DEBUG : x: Need to transfer - File not found at Destination
2023/03/18 17:20:00 ERROR : x: Failed to copy: object not found
2023/03/18 17:20:00 ERROR : Attempt 3/3 failed with 1 errors and: object not found
2023/03/18 17:20:00 INFO  : 
Transferred:   	          0 B / 0 B, -, 0 B/s, ETA -
Errors:                 1 (retrying may help)
Elapsed time:         6.0s

2023/03/18 17:20:00 DEBUG : 5 go routines active
2023/03/18 17:20:00 Failed to copy: object not found

ctrl-q · March 18, 2023, 9:37pm

Some notes

Running rclone copy x main: and rclone copy x main:/xyz works
Adding a local backend as a third upstream and setting create_policy = all resulted in the command succeeding and the file appearing in all three upstreams

asdffdsa · March 18, 2023, 9:42pm

hi,

you are using one remote for the union and main:/xyz is a subdir or main
might that be a problem?

ctrl-q · March 18, 2023, 9:44pm

Hey there, I tried setting the second upstream to a separate OneDrive for Business account and am getting the same result

ncw · March 20, 2023, 11:14am

Does the destination directory xyz exist?

ctrl-q · March 20, 2023, 1:13pm

Yes it does exist

ncw · March 20, 2023, 2:40pm

Can you try using main:xyz instead of main:/xyz - I wonder if that is what is confusing things.

In general remotes should not have a / after the :. On a small number of remotes (ftp, sftp, local, dropbox) it means something different.

ctrl-q · March 21, 2023, 1:24am

Same issue unfortunately

ctrl-q · March 21, 2023, 1:34am

As mentioned in my second comment, the command somehow works if I add a third, non-OneDrive for Business upstream, so I doubt it's got to do with my config

ncw · March 21, 2023, 10:48am

Can you run rclone about on both the upstreams?

rclone about main:
rclone about main:/xyz

If it is the MFS policy misbehaving then it is something to do with the sizes reported.

I wonder if it is getting confused because both the sizes reported for your remotes will always be identical?

ctrl-q · March 29, 2023, 1:15am

here's the output I get for both commands

Total:   1 TiB
Used:    1.453 TiB
Free:    0 B
Trashed: 43.033 GiB

ctrl-q · March 29, 2023, 1:15am

I've also tried setting a completely different oneDrive for Business account as the 2nd remote : same behaviour (object not found)

ncw · March 29, 2023, 7:01am

That says it has no bytes free. This means none of the remotes rclone is trying to use has free space to store things on - this will give the error you see.

ctrl-q · March 30, 2023, 12:09am

Yeah that rclone about command seems wrong for 2 reasons

When I login to the storage metrics page on my OneDrive account, I see I have 122GB free, so I'm not sure how rclone calculates free space
If it really was a free space issue, then the commands in my second comment should also have given the same error

ncw · March 30, 2023, 7:21am

Let's try to find out what is wrong.

Can you do this

rclone about main: -vv --dump bodies

I'm interested in the last REQUEST and RESPONSE which will look like this - can you post those please.

2023/03/30 08:19:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/30 08:19:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/30 08:19:25 DEBUG : HTTP REQUEST (req 0xc00039cb00)
2023/03/30 08:19:25 DEBUG : GET /v1.0/drives/71a96798e7b1d253 HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.63.0-beta.6930.75e385bc4
Authorization: XXXX
Accept-Encoding: gzip

2023/03/30 08:19:25 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/30 08:19:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/30 08:19:25 DEBUG : HTTP RESPONSE (req 0xc00039cb00)
2023/03/30 08:19:25 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: no-store
Client-Request-Id: dd0461f3-7dd9-41be-83d8-404932f57f59
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Thu, 30 Mar 2023 07:19:24 GMT
Odata-Version: 4.0
Request-Id: dd0461f3-7dd9-41be-83d8-404932f57f59
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"UK South","Slice":"E","Ring":"3","ScaleUnit":"003","RoleInstance":"LO2PEPF00000037"}}

167
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#drives/$entity","driveType":"personal","id":"71a96798e7b1d253","owner":{"user":{"displayName":"Nick Craig-Wood","id":"71a96798e7b1d253"}},"quota":{"deleted":580502288,"remaining":15332479830,"state":"normal","total":16106127360,"used":773647530,"storagePlanInformation":{"upgradeAvailable":true}}}
0

2023/03/30 08:19:25 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

ctrl-q · March 31, 2023, 12:01am

Here it is

2023/03/30 18:20:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/30 18:20:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/30 18:20:37 DEBUG : HTTP REQUEST (req 0xc000562600)
2023/03/30 18:20:37 DEBUG : GET /v1.0/drives/<id> HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.61.1
Authorization: XXXX
Accept-Encoding: gzip

2023/03/30 18:20:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/30 18:20:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/30 18:20:37 DEBUG : HTTP RESPONSE (req 0xc000562600)
2023/03/30 18:20:37 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: no-store, no-cache
Client-Request-Id: <id>
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Thu, 30 Mar 2023 22:20:36 GMT
Odata-Version: 4.0
Request-Id: <id>
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: <info>

341
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#drives/$entity","createdDateTime":"2018-05-14T16:19:36Z","description":"","id":"<id>","lastModifiedDateTime":"2023-03-27T14:38:53Z","name":"OneDrive","webUrl":"<account>/Documents","driveType":"business","createdBy":{"user":{"displayName":"Compte syst\u00e8me"}},"lastModifiedBy":{"user":{"email":"<email>","id":"<id>","displayName":"<displayName>"}},"owner":{"user":{"email":"<email>","id":"<id>","displayName":"<displayName>"}},"quota":{"deleted":46206803416,"remaining":0,"state":"exceeded","total":1099511627776,"used":1597364937191}}
0

2023/03/30 18:20:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/30 18:20:37 DEBUG : 5 go routines active

ctrl-q · March 31, 2023, 12:02am

And here's my storage metrics

ncw · March 31, 2023, 7:35am

Thank you.

Here is the relevant quota part of it

  "quota": {
    "deleted": 46206803416,
    "remaining": 0,
    "state": "exceeded",
    "total": 1099511627776,
    "used":  1597364937191
  }

So onedrive definitely thinks you have exceeded your quota as you've used 1.5TB out of 1TB

That says the same thing, that you are using 145% of your quota.

I don't know why it says you have 122 Gb free - that doesn't make sense!

ncw · March 31, 2023, 7:36am

PS Can you upload a large file using the web interface? That will tell us what onedrive really thinks of your quota.

ctrl-q · April 1, 2023, 3:38am

Successfully uploaded a 1GB file through both the web UI and also through rclone

$ head -c 1G /dev/urandom | rclone rcat main:test -P
Transferred:            2 GiB / 2 GiB, 100%, 1.275 MiB/s, ETA 0s
Deleted:                0 (files), 1 (dirs)
Transferred:            1 / 1, 100%
Elapsed time:      11m2.4s