(probably solved) SharePoint fails on syncing uploading a multipart file

Update: I'm using the backup-dir option (with some problems because I wanted to sync from root to root) and so far the problem is not happening. I can only guess that because the files are not overwritten the problem is not happening. Somehow I didn't remember that I had used --backup-dir for something similar in the past.

What is the problem you are having with rclone?

rclone sync from_sharepoint: to_sharepoint: it does (I think!):

  • POST to start a multipart upload
  • PUT to upload the first part
  • PUT gets returned: 404

If I do only the file individually it seems to work (and the log show the same steps). I'm disconcerted by this (I might be missing some SharePoint backend magic).

It seems to do it only when I do rclone sync from_sharepoint: to_sharepoint: (not on doing this file? I need to double check). It always fails on the same files (some in the root of the library, some not). If I copy the file only it works even if rclone is doing for this specific file the same steps (POST, PUT... and then the PUT gets return 200 instead of 404)

What is your rclone version (output from rclone version)

rclone v1.55.0

  • os/type: linux
  • os/arch: amd64
  • go/version: go1.16.2
  • go/linking: static
  • go/tags: cmount

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Debian, stable, 64bits

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

SharePoint

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

rclone -vv --dump requests --log-file=commun-to-test.log --transfers=1 --checkers=1 --ignore-size --ignore-checksum --progress --config config/rclone-config-sharepoint sync Commun-Organisation: test-Commun-Organisation:

The rclone config contents with secrets removed.

[Commun-Organisation]
type = onedrive
token = {"access_token" long JSON}
drive_id = b!SOME_NUMBERS_LETTERS
drive_type = documentLibrary

[test-Commun-Organisation]
type = onedrive
token = {"access_token" long JSON}
drive_id = b!2_SOME_NUMBERS_AND_CHARS_2
drive_type = documentLibrary

A log from the command with the -vv flag

20210325 XXX template document.docx: Starting multipart upload
2021/04/12 13:42:21 DEBUG : HTTP REQUEST (req 0xc0005d6d00)
2021/04/12 13:42:21 DEBUG : POST /v1.0/drives/b!2_SOME_NUMBERS_AND_CHARS_2/items/2_SOME_NUMBERS_AND_CHARS_2:/20210325%20XXX%20template%20document.docx:/createUploadSession HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.55.0
Content-Length: 116
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

{"item":{"fileSystemInfo":{"createdDateTime":"2021-04-12T11:01:49Z","lastModifiedDateTime":"2021-04-12T11:01:49Z"}}}

2021/04/12 13:42:22 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/04/12 13:42:22 DEBUG : HTTP RESPONSE (req 0xc0005d6d00)
2021/04/12 13:42:22 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: no-cache
Client-Request-Id: 1575a733-9d98-4c5b-8f0e-9c34dcf77909
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Mon, 12 Apr 2021 13:42:21 GMT
Location: https://graph.microsoft.com
Odata-Version: 4.0
Request-Id: 1575a733-9d98-4c5b-8f0e-9c34dcf77909
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"North Europe","Slice":"E","Ring":"4","ScaleUnit":"004","RoleInstance":"DB1PEPF00005A85"}}

2021/04/12 13:42:22 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/04/12 13:42:22 DEBUG : 20210325 XXX template document.docx: Uploading segment 0/346702 size 346702
2021/04/12 13:42:22 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/04/12 13:42:22 DEBUG : HTTP REQUEST (req 0xc0001fcf00)
2021/04/12 13:42:22 DEBUG : PUT /sites/l/_api/v2.0/drives/b!2_SOME_NUMBERS_AND_CHARS_2/items/016KXB5TL6QUFIK7PNFVH35OOX2CQ3GBTV/uploadSession?guid=LET_ME_KNOW_IF_YOU_NEED_THIS HTTP/1.1
Host: some_organisation.sharepoint.com
User-Agent: rclone/v1.55.0
Content-Length: 346702
Authorization: XXXX
Content-Range: bytes 0-346701/346702
Accept-Encoding: gzip

lots of binary data

2021/04/12 13:42:22 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/04/12 13:42:22 DEBUG : HTTP RESPONSE (req 0xc0001fcf00)
2021/04/12 13:42:22 DEBUG : HTTP/2.0 404 Not Found
Connection: close
Cache-Control: no-cache

I've hidden strings because I'm not familiar with SharePoint protocol (although I guess that if auth is hidden the rest is not a problem to be there). I'm looking carefully and I see that:

2021/04/12 14:09:53 DEBUG : HTTP REQUEST (req 0xc0015d2a00)
2021/04/12 14:09:53 DEBUG : POST /v1.0/drives/b!DESTINATION_LIBRARY/items/SOME_NUMBERS:/Wording%20for%20cons
istency%20in%20XXX%20documents.docx:/createUploadSession HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.55.0
Content-Length: 116
Authorization: XXXX
Content-Type: application/json
Accept-Encoding: gzip

Returns:

6a5
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#microsoft.graph.uploadSession","expirationDateTime":"2021-04-12T14:24:54.103Z","nextExpectedRanges":["0-"],"uploadUrl":"https://organisation.sharepoint.com/sites/l/_api/v2.0/drives/b!KRI8NPaGoEaIdI4BKGXIpKJtx3RalqNIvG6isH0RPINZqi3FeD7jQIPk8Fevtd4A/items/016KXB5TJHWYI2Z3ZQDRHKOFKS22B7XD56/uploadSession?guid='f6b327db-298f-4c92-964e-35f3ed2b37db'&dc=0&tempauth=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJhdWQiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvc3dpc3Nwb2xhci5zaGFyZXBvaW50LmNvbUBkZTNkYzAyMS1iZTE4LTQ0YzctYjk0NC1mN2IwYWVjMTE3YzYiLCJpc3MiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAiLCJuYmYiOiIxNjE4MjM2NTk0IiwiZXhwIjoiMTYxODMyMjk5NCIsImVuZHBvaW50dXJsIjoicE1oL1NxVkVSVXZTbXhnQWVTQ3RJK3dqbXphblhuNFcxV3NSTGYyd290ST0iLCJlbmRwb2ludHVybExlbmd0aCI6IjIyOSIsImlzbG9vcGJhY2siOiJUcnVlIiwiY2lkIjoiWWpFM01EUTRNV1V0TW1NMU9DMDBZbVk0TFRnNVpEQXRaR1UxTTJFd1lXWTFaVGc0IiwidmVyIjoiaGFzaGVkcHJvb2Z0b2tlbiIsInNpdGVpZCI6Ik16UXpZekV5TWprdE9EWm1OaTAwTm1Fd0xUZzROelF0T0dVd01USTROalZqT0dFMCIsImFwcF9kaXNwbGF5bmFtZSI6InJjbG9uZSIsImdpdmVuX25hbWUiOiJDYXJsZXMiLCJmYW1pbHlfbmFtZSI6IlBpbmEgRXN0YW55Iiwic2lnbmluX3N0YXRlIjoiW1wia21zaVwiXSIsImFjIjoibHxtfGgiLCJhcHBpZCI6ImIxNTY2NWQ5LWVkYTYtNDA5Mi04NTM5LTBlZWMzNzZhZmQ1OSIsInRpZCI6ImRlM2RjMDIxLWJlMTgtNDRjNy1iOTQ0LWY3YjBhZWMxMTdjNiIsInVwbiI6ImNhcmxlcy5waW5hZXN0YW55QHN3aXNzcG9sYXIuY2giLCJwdWlkIjoiMTAwMzIwMDExM0ZFQ0VDRSIsImNhY2hla2V5IjoiMGguZnxtZW1iZXJzaGlwfDEwMDMyMDAxMTNmZWNlY2VAbGl2ZS5jb20iLCJzY3AiOiJteWZpbGVzLnJlYWQgYWxsZmlsZXMucmVhZCBteWZpbGVzLndyaXRlIGFsbGZpbGVzLndyaXRlIGFsbHNpdGVzLnJlYWQiLCJ0dCI6IjIiLCJ1c2VQZXJzaXN0ZW50Q29va2llIjpudWxsfQ.SkFNb2QwbElUUlFFNUsvbDUvQ1lNOStYbGtSU0EvQi9rUlRYUy9rc1hGOD0"}

Then it does the PUT (the string matches with the earlier one):

2021/04/12 14:09:54 DEBUG : HTTP REQUEST (req 0xc0015d3000)
2021/04/12 14:09:54 DEBUG : PUT /sites/l/_api/v2.0/drives/b!KRI8NPaGoEaIdI4BKGXIpKJtx3RalqNIvG6isH0RPINZqi3FeD7jQIPk8Fevtd4A/items/016KXB5TJHWYI2Z3ZQDRHKOFKS22B7XD56/uploadSession?guid='f6b327db-298f-4c92-964e-35f3ed2b37db'&dc=0&tempauth=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJhdWQiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvc3dpc3Nwb2xhci5zaGFyZXBvaW50LmNvbUBkZTNkYzAyMS1iZTE4LTQ0YzctYjk0NC1mN2IwYWVjMTE3YzYiLCJpc3MiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAiLCJuYmYiOiIxNjE4MjM2NTk0IiwiZXhwIjoiMTYxODMyMjk5NCIsImVuZHBvaW50dXJsIjoicE1oL1NxVkVSVXZTbXhnQWVTQ3RJK3dqbXphblhuNFcxV3NSTGYyd290ST0iLCJlbmRwb2ludHVybExlbmd0aCI6IjIyOSIsImlzbG9vcGJhY2siOiJUcnVlIiwiY2lkIjoiWWpFM01EUTRNV1V0TW1NMU9DMDBZbVk0TFRnNVpEQXRaR1UxTTJFd1lXWTFaVGc0IiwidmVyIjoiaGFzaGVkcHJvb2Z0b2tlbiIsInNpdGVpZCI6Ik16UXpZekV5TWprdE9EWm1OaTAwTm1Fd0xUZzROelF0T0dVd01USTROalZqT0dFMCIsImFwcF9kaXNwbGF5bmFtZSI6InJjbG9uZSIsImdpdmVuX25hbWUiOiJDYXJsZXMiLCJmYW1pbHlfbmFtZSI6IlBpbmEgRXN0YW55Iiwic2lnbmluX3N0YXRlIjoiW1wia21zaVwiXSIsImFjIjoibHxtfGgiLCJhcHBpZCI6ImIxNTY2NWQ5LWVkYTYtNDA5Mi04NTM5LTBlZWMzNzZhZmQ1OSIsInRpZCI6ImRlM2RjMDIxLWJlMTgtNDRjNy1iOTQ0LWY3YjBhZWMxMTdjNiIsInVwbiI6ImNhcmxlcy5waW5hZXN0YW55QHN3aXNzcG9sYXIuY2giLCJwdWlkIjoiMTAwMzIwMDExM0ZFQ0VDRSIsImNhY2hla2V5IjoiMGguZnxtZW1iZXJzaGlwfDEwMDMyMDAxMTNmZWNlY2VAbGl2ZS5jb20iLCJzY3AiOiJteWZpbGVzLnJlYWQgYWxsZmlsZXMucmVhZCBteWZpbGVzLndyaXRlIGFsbGZpbGVzLndyaXRlIGFsbHNpdGVzLnJlYWQiLCJ0dCI6IjIiLCJ1c2VQZXJzaXN0ZW50Q29va2llIjpudWxsfQ.SkFNb2QwbElUUlFFNUsvbDUvQ1lNOStYbGtSU0EvQi9rUlRYUy9rc1hGOD0 HTTP/1.1
Host: organisation.sharepoint.com
User-Agent: rclone/v1.55.0
Content-Length: 21270
Authorization: XXXX
Content-Range: bytes 0-21269/21270
Accept-Encoding: gzip

binary data

Then:

2021/04/12 14:09:54 DEBUG : HTTP RESPONSE (req 0xc0015d3000)
2021/04/12 14:09:54 DEBUG : HTTP/2.0 404 Not Found
Connection: close
Cache-Control: no-cache
Content-Security-Policy: frame-ancestors 'self' teams.microsoft.com *.teams.microsoft.com *.skype.com *.teams.microsoft.us local.teams.office.com *.powerapps.com *.yammer.com *.officeapps.live.com *.office.com *.stream.azure-test.net *.microsoftstream.com;
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Mon, 12 Apr 2021 14:09:54 GMT
Expires: -1
Microsoftsharepointteamservices: 16.0.0.21131
Ms-Cv: n72Jew/wACCwUdCTItJQGg.0
Odata-Version: 4.0
P3p: CP="ALL IND DSP COR ADM CONo CUR CUSo IVAo IVDo PSA PSD TAI TELo OUR SAMo CNT COM INT NAV ONL PHY PRE PUR UNI"
Pragma: no-cache
Request-Id: 7b89bd9f-f00f-2000-b051-d09322d2501a
Spclientservicerequestduration: 99
Sprequestguid: 7b89bd9f-f00f-2000-b051-d09322d2501a
Strict-Transport-Security: max-age=31536000
X-Aspnet-Version: 4.0.30319
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Ms-Invokeapp: 1; RequireReadOnly
X-Msedge-Ref: Ref A: F8713EC17C464F4596CC6F85881983C4 Ref B: VIEEDGE1309 Ref C: 2021-04-12T14:09:54Z
X-Powered-By: ASP.NET
X-Sharepointhealthscore: 1
X-Sp-Serverstate: ReadOnly=0

{"error":{"code":"itemNotFound","message":"Item not found"}}

Thank you very much

Message to myself and anyone passing here: two months ago I had problems in the big "file server to SharePoint migration" and I followed: Microsoft OneDrive

In this "SharePoint to SharePoint" copy I should do the same (and will do now) and report if it helps.