One Drive - Failed to copy / Unauthenticated / Expired Token / The access token has expired

@asdffdsa @Ole @ncw

Hello again guys.

Thanks again for everyone's help, and I apologize for any inconvenience and disagreements caused.

If after the logs we don't find any solution I imagine I will have no choice but to try some methodology of partitioning the file as @asdffdsa suggested.

After some tests I understood how the generation of logs works.

Now I'm running the command again to copy the complete 213GB file and the log is being generated, so as soon as the expiration error happens, I'll finish it and post it here so that we can together analyze the errors that appear in the log.

Note : Just a silly question, what is the best way to post the log here? As a file, simply pasting the log, or is there any specific way? Because from what I understand, it will be a very large log.

yeah, we all make a good team,

if the debug log is too large to paste into the forum

  1. upload the file using upload button
  2. use pastebin.com

note: if you do post the full debug, make sure to enclose it with three backticks so it is formated like this

2022/02/22 14:32:03 DEBUG : rclone: Version "v1.57.0" starting with parameters ["C:\\data\\rclone\\rclone.exe" "sync" "b:\\rclone\\vss\\data_files_wasabi_en07-data-crypt_20220222.143200\\data" "wasabi_en07-data-crypt:en07data/rclone/backup" "--backup-dir=wasabi_en07-data-crypt:en07data/rclone/archive/20220222.143200" "--stats=5h" "--fast-list" "--s3-no-check-bucket=true" "--exclude-from=C:\\data\\rclone\\rr\\data\\rclone.exclude.txt" "--config=C:\\data\\rclone\\rclone.conf" "--ask-password" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\logs\\data_files_wasabi_en07-data-crypt\\20220222.143200\\rclone.log"]
2022/02/22 14:32:03 DEBUG : Creating backend with remote "b:\\rclone\\vss\\data_files_wasabi_en07-data-crypt_20220222.143200\\data"
2022/02/22 14:32:03 DEBUG : Using config file from "C:\\data\\rclone\\rclone.conf"

@asdffdsa @Ole @ncw

Hey guys !

I'm back, and now I've had time to let the log run for quite some time.

I couldn't fully scrutinize the file, I looked for failures like "Error" and also "Expired" I found some, but I really don't know how to proceed from this anymore, I also saw that at times a "pacer" warning appeared in DEBUG.

Also, I found "Too many requests" alerts.

I don't know if this has anything to do with it... I redacted all the information I thought was necessary, but I imagine that nothing that gets in the way of the search for a possible solution.

Also, I haven't finished it yet, it's still running until now... I don't know if it's just me, but it seems that the upload hasn't been canceled yet? As if it's still in progress, even though it's been more than 24 hours since the upload has been running.

Note : As expected, the file got too big, so I reduced the size of the log, deleting part of what happened during this night, however I checked completely before deleting and it was just more of the same (current time, copy status and current sector of the file).

Your turn guys.

Thank you all.

Rclone Sync Expired Token.txt (3.3 MB)

hi,
i took a quick look at the debug log,

those pacer messages and error 503 Service Unavailable are to be expected.

multiple times, there is expected behavior

2022/02/24 15:14:38 DEBUG : One Drive: Loaded invalid token from config file - ignoring
2022/02/24 15:14:39 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 15:14:39 DEBUG : One Drive: Saved new token in config file

but that large .vhd file, fails to upload and rclone had to retry.

2022/02/24 12:50:28 ERROR : Attempt 1/3 failed with 1 errors and: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'.
2022/02/24 12:50:28 NOTICE: WindowsImageBackup/SERVER-TOTVS/Backup 2022-01-05 205054/b244b864-dea4-11e7-b563-806e6f6e6963.vhd: Failed to cancel multipart upload: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'. (upload failed due to: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'.)
2022/02/24 12:50:28 ERROR : WindowsImageBackup/SERVER-TOTVS/Backup 2022-01-05 205054/b244b864-dea4-11e7-b563-806e6f6e6963.vhd: Failed to copy: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'.

Here is an exceprt from the log

$ grep -P "Saving config|ERROR" Rclone\ Sync\ Expired\ Token.txt
2022/02/23 13:46:09 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 17:46:04 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 18:53:02 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 19:56:59 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 21:07:32 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 22:14:41 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/23 23:29:27 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 00:57:14 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 02:04:04 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 03:22:55 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 04:39:42 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 06:02:37 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 07:21:06 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 08:50:43 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 09:57:49 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 11:24:54 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 12:41:41 DEBUG : Saving config "token" in section "One Drive" of the config file
2022/02/24 12:50:28 ERROR : WindowsImageBackup/SERVER-TOTVS/Backup 2022-01-05 205054/b244b864-dea4-11e7-b563-806e6f6e6963.vhd: Failed to copy: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'.
2022/02/24 12:50:28 ERROR : Attempt 1/3 failed with 1 errors and: unauthenticated: expiredToken: The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'.

You can see rclone refreshing the token (at somewhat irregular intervals).

It refreshes at 12:41 which is only 9 minutes before the error at 12:50.

The backup of this file started at 2022/02/23 12:45:25 and the error was received at 2022/02/24 12:50:28 which is 24 hours plus 5 minutes.

It said in the message

The access token has expired. It's valid from '2/23/2022 3:45:26 PM' and to '2/24/2022 3:45:26 PM'

We don't know what timezone that error message is in, but it looks very much like the token was granted at 2022/02/23 12:45:25 exactly when the file upload started and expired 24h later.

So I think this isn't the normal oauth token - that seems to be refreshed just fine.

This must be the validity of the multipart upload session.

The docs for that are in the resumable upload section.

When rclone creates the resumable upload session it gets an expiry date back so I'd guess that if we looked in that response it would be 24h from the initial upload.

I didn't find anywhere in Microsoft's docs that indicates a way of extending the time - it would be great if interested parties could take a look too and double check.

If there isn't a way if extending then we are limited to being able to upload the file in 24h (or whatever microsoft set the expiration date to).

You could raise an issue here GitHub - OneDrive/onedrive-api-docs: Official documentation for the OneDrive API (or I can do it for you) asking how you upload a file which takes longer than 24 hours.

But, for the moment at least, it seems this isn't possible and your solution is going to be to use chunker.

does that provide any info?

I think those are session tokens not "upload session" tokens so probably different things. Not 100% sure though!

Agree with all the above. Everything looks fine, there is no extensive throttling or other issues, just seems like OneDrive doesn’t like single file uploads taking more than 24 hours.

You unfortunately used --stats=36h (output a stats line every 36 hour) instead of the proposed --stats=15m (every 15 minutes), so it is difficult to spot changes in transfer speed. I did however do a few samples of the time spent for some multiparts and it seems be pretty constant around the 2 MiB/s we have seen earlier.

I just tried a single file upload of 1GB and it was performed with almost 20 MiB/s and your connection allows uploads around 15 MiB/s, so there may be something in your local setup limiting the upload speed. Here are some questions to investigate this further if you wish:

What transfer speed did you see when you tried with the smaller 200MB file?

What speed do you see if you upload to another service (e.g. a free 15GB Google Drive)?

First, thank you all for the information.

@ncw

Well, I've never created any posts on GitHub, so if you could raise the issue for us, and post it here I'd find a way to follow the discussions.

@ole

Sorry, about this --stats=36 issue, it was totally my fault, I was developing another script and ended up making this mistake. If necessary I can run it again and now with the correct syntax, but it would take a long time.

Still on this about the transfer speed for a smaller item is the same. I even just did a test upload of a smaller item, approximately 500mb and this time I generated the log correctly, put --stats=15s, the peak speed was around 3.5 Mb/s and the rest is still the same, and with the same variations. But in general, it's still a speed well below the true capacity of my connection.

Rclone.txt (7.1 KB)

I imagine that this log serves in some way to make a better analysis instead of my previous error about the question of --stats=36h.

But generally speaking, this is always the speed I get regardless of the file size.

I will test this on Google Drive.

About settings and blocking, I'm very strict with security here, and in fact I have a deny all on my firewall and I only release what I think is necessary, mainly for things external to the internal network, so I don't know if there would be any possible partial blockage that may be hindering the upload, such as a specific port on One Drive, for example, or even for any cloud in general.

I imagine that we will clear this doubt as soon as I test it through Google Drive.

Now a question about the chunker, can I create a chunk in another folder, but within this same cloud where I normally upload my files? Because the idea would be to use my scripts normally even at low speed if we don't solve this, but for this larger file, I would create a different command where only the chunk would be used in it, however, the folder structure of my cloud would remain the same except for this specific file that would be chunked.

@asdffdsa

Maybe you can explain more about this chunked issue to me, so I'll do some testing before actually using this method.

Of course, following some documentation that you guys recommend so that I can understand better about it.

hi, sorry never used it, never had issues uploading 300+GiB files on a regular basis
not sure it will workaround your issue, would not increase the upload speed, thus the 24hr token issue would remain.

not sure about your exact use-case but:
i am a big fan of wasabi.
tho could use gdrive with a service file account, and perhaps even using a token.

if you try one of my other sugeestions, i can help with that.

I guess a copy with chunker will complete even if taking more than 24 hours as long as each of the individual chunks are transferred in less than 24 hours. As an example: A chunksize of 50 GB and --transfers=1. But this is just guessing based on the documentation, the chunker backend is in BETA and I haven't tried either.

Personally, I would be very cautious to use this or other chunking options before having carefully considered the additional complexity and risks involved in a restore or fallback situation.

I made an issue here: Can't upload files which take longer than 24 hours using resumable upload · Issue #1570 · OneDrive/onedrive-api-docs · GitHub

Let's hope someone at Microsoft takes a look :slight_smile:

there seems to be a hard 24hr limit for onedrive business tokens.
imho, not a bug, instead an intentional design choice.

2022/02/25 11:49:42 DEBUG : rclone: Version "v1.57.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone.exe" "copy" "v:\\vm\\server02\\drivec.vhdx" "onedrivevb:zork" "--log-level=DEBUG" "--log-drivec=.\\\\onedrive.24.txt" "--progress" "--bwlimit=0.5m"]
2022/02/25 11:49:42 DEBUG : Creating backend with remote "v:\\vm\\server02\\drivec.vhdx"
2022/02/25 11:49:42 DEBUG : Using config drivec from "c:\\data\\rclone\\scripts\\rclone.conf"
2022/02/25 11:49:42 DEBUG : fs cache: adding new entry for parent of "v:\\vm\\server02\\drivec.vhdx", "//?/v:/vm/server02"
2022/02/25 11:49:42 DEBUG : Creating backend with remote "onedrivevb:zork"
2022/02/25 11:49:44 DEBUG : drivec.vhdx: Need to transfer - drivec not found at Destination
2022/02/25 11:49:44 DEBUG : drivec.vhdx: Starting multipart upload
2022/02/25 11:49:45 DEBUG : drivec.vhdx: Uploading segment 0/222965006336 size 10485760
.....

2022/02/26 11:55:11 DEBUG : drivec.vhdx: Cancelling multipart upload: unauthenticated: expiredToken: The access token has expired. It's valid from '2/25/2022 4:49:44 PM' and to '2/26/2022 4:49:44 PM'.
2022/02/26 11:55:12 NOTICE: drivec.vhdx: Failed to cancel multipart upload: unauthenticated: expiredToken: The access token has expired. It's valid from '2/25/2022 4:49:44 PM' and to '2/26/2022 4:49:44 PM'. (upload failed due to: unauthenticated: expiredToken: The access token has expired. It's valid from '2/25/2022 4:49:44 PM' and to '2/26/2022 4:49:44 PM'.)
2022/02/26 11:55:12 ERROR : drivec.vhdx: Failed to copy: unauthenticated: expiredToken: The access token has expired. It's valid from '2/25/2022 4:49:44 PM' and to '2/26/2022 4:49:44 PM'.
2022/02/26 11:55:12 ERROR : Attempt 1/3 failed with 1 errors and: unauthenticated: expiredToken: The access token has expired. It's valid from '2/25/2022 4:49:44 PM' and to '2/26/2022 4:49:44 PM'.
2022/02/26 11:55:13 DEBUG : drivec.vhdx: Need to transfer - drivec not found at Destination
2022/02/26 11:55:13 DEBUG : drivec.vhdx: Starting multipart upload
1 Like

Hello again guys,

I apologize for making you wait so long.

After all these questions, and as we also didn't get any answer from Microsoft itself on GitHub, the reality is that the only two solutions will be, partition the file or solve the connection speed problem.

For the first solution, we know that there are several ways to do this, but I still haven't had time to look for them and put them into practice.

Thinking about the second solution I did what @Ole gave the idea, to test via another provider, and thinking about it first I tried to upload the file directly through the browser but still on One Drive, and there, the upload showed a considerable speed higher, above 15 Mb/s I don't remember exactly.

Also, I tested the file upload by Rclone but instead of One Drive I used Google Drive, and there I got excellent results at an average of 16~17 Mb/s which matches my real connection.

image

For this case, I'm sending a log where I uploaded about 10 GB of data to Google Drive via Rclone, with the same command, just changing the One Drive remote to Google Drive.

Rclone Google Drive.txt (125.2 KB)

So guys, is there any explanation and any solution for why the One Drive upload works so badly on Rclone?

Anyway, I look forward to your experienced answers.

Ty again.

Hi again Dorkens,

Interesting, I suggest we make a little test to see if we can find the root cause.

The test consists of three different uploads of your 10GB file, the uploads should be performed in a row to eliminate day-to-day variations in the speed of your internet and OneDrive. These are the steps:

First create /local-testpath/ and remote:/cloud-testpath/ - both should be empty.

Then copy your 10 GB testfile to /local-testpath/

Then execute this command:

rclone sync --ignore-time /local-testpath/ remote:/cloud-testpath/ --log-file=/local-home/10GBnormal.log --stats-one-line --stats=15s -vv

When finished execute this command: (it is the same as the previous, but with --disable-http2 added and another logfile)

rclone sync --ignore-time /local-testpath/ remote:/cloud-testpath/ --log-file=/local-home/10GBnohttp2.log --stats-one-line --stats=15s -vv --disable-http2

When finished upload the file using the OneDrive web interface in your browser (on the same computer as rclone) from/to the same folders as above. Manually note upload time and speed.

This will hopefully give us information to narrow in on the issue.

Note my edit, I changed --ignore-size to --ignore-time above.

In case you foresee an increase in the size of your backup; I have just discovered that the size of your current backup is 85% of the maximum file size in OneDrive: https://rclone.org/onedrive/#file-sizes

Nice.

I did the commands and generated the logs, I just did it with a smaller file because with 10GB it could take hours and hours to finish each log, but I imagine the result should be the same.

10GBnormal.log (17.5 KB)
10GBnohttp2.log (16.3 KB)

Anyway, as you can see in the logs, we didn't have any success.

As for sending through the browser, I got a good speed :

image

1.28GB in 1:34s which would be approximately 9.5~10 Mb/s.

Which is an improvement, but still not the 15~17 Mb/s of Google Drive via Rclone.

(I used the same computer and system where I use Rclone for browser upload.)

One thing about that :

Just an addendum, that I could notice that the correct flag is --ignore-times instead of --ignore-time, otherwise it will throw an error in Rclone.

This is really relevant information in the long term.

Well ...

Strange situation, it seems that my system doesn't like One Drive, either in Rclone or in the browser.

There is finally an answer on GitHub

To support uploads longer 24hrs, this would be a new feature request.
Please work with your support contact to lodge a feature request.

Which I guess means that the 24 hour limit is intentional, and that you might be able to raise an issue with your support contact to change it.

Interesting, this in itself could serve as a solution as well. As much as it's not ideal, it can work.