InvalidAuthenticationToken: Unable to initalize RPS

ncw · April 19, 2021, 9:35pm

Interesting...

Can you capture a log with -vv --dump bodies of that and post it? Or if it has got confidential stuff, PM me with a link.

jared · April 19, 2021, 10:23pm

it's funny that you mentioned that. I too thought it was basically on high filie-count remotes, as that's largely where i had the problem. but i just ls'ed a 400,000-file remote TWICE in pursuit of the error; no joy..

ncw · April 20, 2021, 10:04am

I suspect this is a bug in onedrive which will be fixed fairly quickly, but if one of you can catch a failing http transaction I can report it to microsoft via a github that they do look at and fix bugs reported there.

Philippe48 · April 20, 2021, 1:57pm

Since 03:00 am (Belgium), I no longer receive an error. Everything works as before !

ncw · April 20, 2021, 3:28pm

That is good! Anyone else still seeing the problem?

jared · April 20, 2021, 3:41pm

yes. just caught it at -vv level with --dump bodies flag. It's mentioning something about the AutenticationToken being invalid. i'll PM you the log in a minute.

jared · April 20, 2021, 3:57pm

lol. i guess that's literally the title of the post.....which i created anyway. log in your inbox bud.

ncw · April 20, 2021, 4:27pm

Thank you for the log.

I put a very small part of that log into the issue I reported to Microsoft: Random "InvalidAuthenticationToken: Unable to initialize RPS" have started appearing · Issue #1489 · OneDrive/onedrive-api-docs · GitHub

Let's see what they have to say!

jared · April 20, 2021, 4:37pm

alright. sounds good. hopefully this isn't a move against rclone directly.

Ole · April 20, 2021, 5:46pm

Thanks for an excellent tool and forum!

I have managed to collect some additional information using rclone 1.54.1 and Windows Powershell (5.1) on my personal OneDrive. It is a premium account with app. 70.000 files and 300Gb - mostly Photos, Videos and Office documents.

These are the commands used to capture the information:

rclone check OneDrive: OneDriveClient: --checkers 32 --log-file AuthIssue.txt --log-level DEBUG --dump 'requests,responses'
Get-Content AuthIssue.txt | Select-String 'DEBUG : HTTP' > AuthIssueHTTP.txt
 
# I do have a few additional rclone parameters in my environment variables, but believe they have no impact on this issue. 
# The remote OneDrive: uses the rclone client ID and the remote OneDriveClient: uses my own client ID, but the client ID does not seem to influence this issue.

I ran the commands a few times in a row and then the issue was quite reproducible for a while. The affected folders were random from execution to execution and mostly contained simple content: Photos, Office Documents, PDF, or similar - nothing to trigger warnings of malware or illegal content.

In one of the executions, I got a good HTTP trace starting early in the 300MB log. The condensed and annotated debugging information follows at the end of the post. I have added annotation to show the relationship between the failing HTTP requests and the "401/Unable to initialize RPS" responses. I then tried to find the pattern where requests lead to failing responses.

Based on the analysis I guess that OneDrive returns the "401/Unable to initialize RPS" when A) somebody makes a lot of almost simultaneous requests and B) that somebody have made many requests within the past minutes/hours and C) some part of the OneDrive infrastructure is near the upper limit. The responses come much quicker than the ordinary 200/OK and therefore appears to take the pressure of OneDrive and return a quick distress signal to the most active clients. Somebody could be a combination Microsoft account, client id, IP address, …

So "401/Unable to initialize RPS" may just be OneDrive’s way of snarling: "I am stressed, and you are pushing me. Reduce activity!". It may be triggered by an overload/DoS prevention system before the request reaches the actual Microsoft Graph servers.

If my analysis is correct, then a solution could be to handle intermittent "401/Unable to initialize RPS" responses somewhat like "429/Too Many requests". That is low level retries with gradually decreasing pace.

I am by the way pretty sure I have seen somewhat similar behavior with intermittent 50x responses from OneDrive. They may be candidates for a similar treatment, if this is not already the case.

@Philippe48: I have just tried again and can confirm that I see no issues now.
@jared, @ncw: Do you see the same pattern as me in your trace?

And now to the details for those interested...

This is first HTTP response with the "Unable to initialize RPS" response (The time is CET/Denmark):

2021/04/20 11:37:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
Transfer-Encoding: chunked
Client-Request-Id: 21939f32-0fb4-4a68-ba00-9ff343dc66fe
Content-Type: application/json
Date: Tue, 20 Apr 2021 09:37:08 GMT
Request-Id: 21939f32-0fb4-4a68-ba00-9ff343dc66fe
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
Www-Authenticate: Bearer realm="", authorization_uri="https://login.microsoftonline.com/common/oauth2/authorize", client_id="00000003-0000-0000-c000-000000000000"
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"West Europe","Slice":"E","Ring":"5","ScaleUnit":"004","RoleInstance":"AM2PEPF00005E95"}}

130
{
  "error": {
    "code": "InvalidAuthenticationToken",
    "message": "Unable to initialize RPS",
    "innerError": {
      "date": "2021-04-20T09:37:08",
      "request-id": "21939f32-0fb4-4a68-ba00-9ff343dc66fe",
      "client-request-id": "21939f32-0fb4-4a68-ba00-9ff343dc66fe"
    }
  }
}
0

2021/04/20 11:37:11 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

This is corresponding request:

2021/04/20 11:37:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4500)
2021/04/20 11:37:11 DEBUG : GET /v1.0/drives/8a04b78b37b96c04/items/8A04B78B37B96C04!418/children?$top=1000 HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.54.1
Authorization: XXXX
Accept-Encoding: gzip

2021/04/20 11:37:11 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

This is the condensed HTTP communication:

2021/04/20 11:37:09 DEBUG : HTTP REQUEST (req 0xc000389200)
2021/04/20 11:37:10 DEBUG : HTTP RESPONSE (req 0xc000389200)
2021/04/20 11:37:10 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:10 DEBUG : HTTP REQUEST (req 0xc000128d00)
2021/04/20 11:37:10 DEBUG : HTTP RESPONSE (req 0xc000128d00)
2021/04/20 11:37:10 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:10 DEBUG : HTTP REQUEST (req 0xc00050ec00)
2021/04/20 11:37:10 DEBUG : HTTP REQUEST (req 0xc000389800)
2021/04/20 11:37:10 DEBUG : HTTP RESPONSE (req 0xc000389800)
2021/04/20 11:37:10 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050ec00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f100)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0005d7900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000388800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000388f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050ee00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000129a00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045c400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045c900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050fd00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045d200)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000389800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092e100)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000389e00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8e00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092e800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092f000)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092f500)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9600)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5d00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7a300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092e400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045c200)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045cb00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045d300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045d900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7a900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092ec00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045df00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7ae00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050ea00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092f600)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7b300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f500)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050fe00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000388b00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000389500)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000389c00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4500)  -1-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7ba00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8f00)  -2-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4500) <-1- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized           
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0005d7900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e8f00) <-2- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized       
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e8800)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000388f00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000388800)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050f100)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000129a00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8500)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8b00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9700)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9c00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7a500)  -3-> 401 Unautherized 
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000389e00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050f900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4b00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045c500)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050ee00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7a500) <-3- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045d200)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092e800)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050fd00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5200)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000129d00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4300)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000389800)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e8300)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092e100)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7ac00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092f000)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f300)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045c400)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000388100)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000389400)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d5400)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e9600)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092f500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5e00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045d600)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092ea00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045dd00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000b7b600)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e2400)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e8e00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092f700)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e2900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e2d00)  -4-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e3200)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d5d00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092e400)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092fb00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7a300)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092ff00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009e2d00) <-4- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8000)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e3800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158000)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0011d8000) <-5- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158500)  -6-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8500)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045d300)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158a00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009e3c00)  -7-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045df00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001158500) <-6- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328a00)  -8-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7ae00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8a00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8f00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009e3c00) <-7- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8200)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328200)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045c200)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045d900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001328a00) <-8- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158300)  -9-> 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328b00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000389500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8d00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7b300)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8700)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d9800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d9c00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001158300) <-9- 401 Unautherized
2021/04/20 11:37:11 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092f600)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045cb00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001329100)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e8500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050f500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000129d00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9e00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000129a00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045c500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d5200)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050ef00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158d00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4400)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7ba00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d4b00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d4700)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001329400)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7a900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050fe00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009d5e00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158700)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001158300)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009e3200)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7ac00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f000)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00045dd00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092f700)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0008e9700)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092ea00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5000)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001328400)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009e2900)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001158000)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328600)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00050f800)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00050ea00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092ff00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc00092fb00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8100)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0009e3800)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001328f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001329a00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001159400)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001329f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0009d5a00)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0011d8500)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000b7b600)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc000129f00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d8c00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00045c400)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc000389c00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001159900)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0011d9300)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc0011d8a00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e8800)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc001159e00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092e300)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9100)
2021/04/20 11:37:11 DEBUG : HTTP RESPONSE (req 0xc001158f00)
2021/04/20 11:37:11 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc00092ed00)
2021/04/20 11:37:11 DEBUG : HTTP REQUEST (req 0xc0008e9a00)  -10-> 401 Unautherized
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0008e9a00) <-10- 401 Unautherized
2021/04/20 11:37:12 DEBUG : HTTP/1.1 401 Unauthorized
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0011d8200)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc001329100)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0008e9300)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0008e9e00)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc0011d9e00)
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc000388800)
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc000129a00)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc00045d600)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc00045cd00)
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc000389100)
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc000389800)
2021/04/20 11:37:12 DEBUG : HTTP REQUEST (req 0xc00045d200)
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc001158d00)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0008e9c00)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
2021/04/20 11:37:12 DEBUG : HTTP RESPONSE (req 0xc0009e2400)
2021/04/20 11:37:12 DEBUG : HTTP/1.1 200 OK
...

ncw · April 20, 2021, 9:24pm

That is very interesting analysis.

You could test your theory by adding --tpslimit and seeing if you can get it to run clean with a certain value of --tpslimit.

At the moment rclone is handling the 401 errors as fatal errors I think. It might also be trying to refresh the token but if it is, that isn't appearing in the debug log for some reason.

I made a similar analysis of the log @jared sent me and it was more like 50% of transactions failing there.

Semyon_O · April 21, 2021, 6:06am

21 April, and the issue is still there for ~1 AM. --tpslimit is set to 1, so lowering number of requests does not seem to help much.
Checking at ~9AM, and the issue does not appear. Nothing changed since last try. Hope it is fixed.

Philippe48 · April 21, 2021, 9:28am

Bad news. The errors reappeared ....(03:00 GMT +2)

dsteinkopf · April 21, 2021, 10:42am

Am also still having this problem for some days now (exactly since Apr 17). Analysis of my logs revealed that the problem already existed on Apr 9.
(I am updating rclone on a daily basis).

Ole · April 22, 2021, 7:00pm

The issue seems independent of bursts. @Semyon_O is absolutely correct, there are also errors with tpslimit set to 1 request/second. The proportion of errors doesn't change significantly when reducing the speed.

The issue also seems independent of the number of previous requests. I have compared the issue rate between two different client IDs. One of them was heavily loaded first, the other was completely fresh when starting. They showed similar frequency of issues, but not necessarily at the same times.

The issue seems related to the load on the regional Microsoft servers. While testing I observed that the issue is much more frequent in extended office hours (8:00 - 20:00). The issue was more seldom outside these hours and almost vanished in the late evening.

Based on this it may be possible for some to do a scheduling work around by rcloning OneDrive when there is low (business) activity on their regional servers.

Some may need to rclone in business hours, and I have therefore played with a workaround patch to rclone. This is the new "else if" to be added in line 569 of onedrive.go to do a simple work around:

switch resp.StatusCode {
	case 401:
		if len(resp.Header["Www-Authenticate"]) == 1 && strings.Index(resp.Header["Www-Authenticate"][0], "expired_token") >= 0 {
			retry = true
			fs.Debugf(nil, "Should retry: %v", err)
		} else if err != nil && strings.Contains(err.Error(), "Unable to initialize RPS") {
			retry = true
			fs.Debugf(nil, "HTTP 401: Unable to initialize RPS. Trying again.")
		}
	case 429: // Too Many Requests.

It handles the issue with low level retries. The low level retries will help us finish the syncs in the first attempt and it will also help Microsoft by reducing our rclone load with fewer syncing attempts. This patch made my rclone check complete in the first attempt with 111 low level retries, that all succeeded in the first retry.

Here is a more friendly work around where rclone gives some room to Microsoft (and their other customers) in a pressed situation:

switch resp.StatusCode {
	case 401:
		if len(resp.Header["Www-Authenticate"]) == 1 && strings.Index(resp.Header["Www-Authenticate"][0], "expired_token") >= 0 {
			retry = true
			fs.Debugf(nil, "Should retry: %v", err)
		} else if err != nil && strings.Contains(err.Error(), "Unable to initialize RPS") {
			retry = true
			retryAfter := 1
			duration := time.Second * time.Duration(retryAfter)
			err = pacer.RetryAfterError(err, duration)
			fs.Debugf(nil, "HTTP 401: Unable to initialize RPS. Trying again in %d seconds.", retryAfter)
		}
	case 429: // Too Many Requests.

More testing is needed to evaluate whether 1 second strikes the right balance in all use cases and regions. I personally wouldn't hesitate to accept up to 10 seconds, just to get my sync completed in first attempt and to compensate for the fact that the "401/Error" response comes quicker than the "200/OK" response. Without a delay rclone would actually increase the requests per second in a situation where the OneDrive servers might be under pressure.

I will leave it up to the rclone core team to decide which if any of the work around patches to implement. I am pretty new to rclone and this is litterally my "Hello World" in Go, so careful review and test are highly recommended

Jenssaibe · April 22, 2021, 7:25pm

Impressive. Great work man.

ncw · April 22, 2021, 7:45pm

That looks very nice.

Do you want to propose a PR with one or the other of those in?

Note that if you set retry then rclone will do an exponential backoff, so probably your first patch is fine.

Ole · April 24, 2021, 4:18pm

FYI: The work around is in the pipeline

github.com/rclone/rclone

Work around for "Unable to initialize RPS" errors from OneDrive

opened 12:16PM - 23 Apr 21 UTC

olefrost

OneDrive returns occasional http 401 responses with the error message: "InvalidA…uthenticationToken: Unable to initialize RPS". The frequency varies and has been increasing lately. It may be related to a bug and/or high load on Microsoft servers. The unexpected 401 response leads to sync failurers etc. for many users: https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595 The issue impacts all commands using the OneDrive backend in rclone 1.55.0 (and earlier) on all platforms. The issue has been reported to Microsoft in this bug report: https://github.com/OneDrive/onedrive-api-docs/issues/1489 This enhancement will increase the robustness of the OneDrive backend by implementing the first work around in this forum post: https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595/35

github.com/rclone/rclone

onedrive: Work around for random "Unable to initialize RPS" errors

rclone:master ← olefrost:fix-5270-unable-to-initialise-rps

opened 04:07PM - 24 Apr 21 UTC

olefrost

+3 -0

#### What is the purpose of this change? OneDrive randomly returns the error message: "InvalidAuthenticationToken: Unable to initialize RPS". These unexpected errors typically caused the entire rclone command to fail. This work around recognizes these errors and marks them for a low level retry, that mostly succeeds. This will make rclone commands complete without being noticeable affected. Fixes: #5270 #### Was the change discussed in an issue or in the forum before? This change contains the simple work around proposed in this post: https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595/35 This is the approval and comments from @ncw: https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595/37 I decided to go with Nicks recommendation to reduce testing and potential negative side effects. During test I discovered that the rclone pacer actually does an automatic 20ms back off on a simple retry :) #### Checklist - [X] I have read the [contribution guidelines](https://github.com/rclone/rclone/blob/master/CONTRIBUTING.md#submitting-a-pull-request). - [ ] I have added tests for all changes in this PR if appropriate. - [ ] I have added documentation for the changes if appropriate. - [X] I have tested the change in situations where the code becomes active (see below) - [X] I have tested the change on my daily rclone jobs (see blow) - [X] All commit messages are in [house style](https://github.com/rclone/rclone/blob/master/CONTRIBUTING.md#commit-messages). - [X] I'm done, this Pull Request is ready for review :-) #### Test documentation ##### Test environment rclone v1.56.0-DEV - os/version: Microsoft Windows 10 Pro 2009 (64 bit) - os/kernel: 10.0.19042.928 (x86_64) - os/type: windows - os/arch: amd64 - go/version: go1.16.3 - go/linking: dynamic - go/tags: none _Note: Rclone was compiled with go1.16.3 without the cmount tag. This is slightly different from the rclone baseline, but considered acceptable to test this specific change._ ##### Test cases Re-executed the tests in these posts: https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595/30 https://forum.rclone.org/t/invalidauthenticationtoken-unable-to-initalize-rps/23595/35 Executed my personal backup scripts with multiple rclone syncs to/from OneDrive. (with and without --dry-run) ##### Test Results Condensed extract from one of the log-files: ``` >Get-Content $authlog | Select-String 'DEBUG : rclone','DEBUG : HTTP','DEBUG : pacer' 2021/04/23 16:54:20 DEBUG : rclone: Version "v1.56.0-DEV" starting with parameters ["C:\\Users\\Ole\\go\\bin\\rclone.ex e" "check" "OneDrive:" "OneDriveClient:" "--checkers" "32" "--progress" "--stats" "10s" "--log-file" "logs\\AuthIssueTe st_2021-04-23_1653.txt" "--log-level" "DEBUG"] 2021/04/23 16:54:45 DEBUG : HTTP 401: Unable to initialize RPS. Trying again. 2021/04/23 16:54:45 DEBUG : pacer: low level retry 1/10 (error InvalidAuthenticationToken: Unable to initialize RPS) 2021/04/23 16:54:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2021/04/23 16:54:45 DEBUG : pacer: Reducing sleep to 15ms 2021/04/23 16:54:45 DEBUG : pacer: Reducing sleep to 11.25ms 2021/04/23 16:54:45 DEBUG : pacer: Reducing sleep to 10ms 2021/04/23 16:54:46 DEBUG : HTTP 401: Unable to initialize RPS. Trying again. 2021/04/23 16:54:46 DEBUG : pacer: low level retry 1/10 (error InvalidAuthenticationToken: Unable to initialize RPS) 2021/04/23 16:54:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 15ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 11.25ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 10ms 2021/04/23 16:54:46 DEBUG : HTTP 401: Unable to initialize RPS. Trying again. 2021/04/23 16:54:46 DEBUG : pacer: low level retry 1/10 (error InvalidAuthenticationToken: Unable to initialize RPS) 2021/04/23 16:54:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 15ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 11.25ms 2021/04/23 16:54:46 DEBUG : pacer: Reducing sleep to 10ms ... 2021/04/23 16:55:33 NOTICE: One drive root '': 0 differences found 2021/04/23 16:55:33 NOTICE: One drive root '': 69743 matching files 2021/04/23 16:55:33 INFO : Transferred: 0 / 0 Bytes, -, 0 Bytes/s, ETA - Checks: 69743 / 69743, 100% Elapsed time: 1m14.0s 2021/04/23 16:55:33 DEBUG : 5 go routines active ```

ncw · April 24, 2021, 10:06pm

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.56 - thank you @Ole

dsteinkopf · April 25, 2021, 5:15am

Thank you very much. The latest Beta does the trick for me. No error anymore.