When does Rclone decide to refresh a Google token?

Help and Support
1

What is the problem you are having with rclone?

During a long copy (24+ hours), I see periodic stretches of errors like this:

2021/07/30 19:40:03 ERROR : 3.jpg: Failed to copy: googleapi: Error 401: Invalid Credentials, authError
2021/07/30 19:44:42 ERROR : 4.jpg: Failed to copy: couldn't list directory: googleapi: Error 401: Invalid Credentials, authError

After some minutes, Rclone will self-correct and resume copying files, presumably because it has obtained a new access token. What I don't understand is why there are these periods when Rclone will continue trying to use the bad token.

What is your rclone version (output from rclone version)

v1.55.1

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

Windows 10, 64 bit

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

Google Drive

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

2021/07/29 15:09:30 DEBUG : rclone: Version "v1.55.1" starting with parameters ["C:\\Program Files\\Rclone\\rclone.exe" "copy" "--config" "C:\\Users\\Chad\\AppData\\Local\\Temp\\tmpA3E2.tmp" "--log-file" "C:\\Temp\\user.log" "--max-backlog" "1000000" "--stats-one-line-date" "--log-level" "DEBUG" "--max-depth" "20" "--drive-server-side-across-configs" "SourceMyDrive:" "SharedDrive:"]

The rclone config contents with secrets removed.

[SourceMyDrive]
type = drive
scope = drive
service_account_file = C:\Temp\source.json
impersonate = user@example.org

[SharedDrive]
type = drive
scope = drive
team_drive = 1BNja75gSBt9bVl0OWB
service_account_file = C:\Temp\source.json
impersonate = user@example.org

A log from the command with the -vv flag

2021/07/30 19:08:17 INFO  : 1.jpg: Copied (server-side copy)
2021/07/30 19:08:17 INFO  : 2.jpg: Copied (server-side copy)
2021/07/30 19:40:03 ERROR : 3.jpg: Failed to copy: googleapi: Error 401: Invalid Credentials, authError
2021/07/30 19:44:42 ERROR : 4.jpg: Failed to copy: couldn't list directory: googleapi: Error 401: Invalid Credentials, authError
2021/07/30 19:44:48 INFO  : 5.jpg: Copied (server-side copy)
2021/07/30 19:44:49 INFO  : 6.jpg: Copied (server-side copy)

I am assuming it is a stale access token, but I don't know that for sure and see nothing in the log about requesting a new one. Note that this is using a service account without end-user interaction, and there is no refresh token specified in the config file.

One wrinkle here that I suspect may come into play is that this is running on a VM on my laptop, and I have seen periods of time where the VM is put into a suspended mode. I can't definitively map any such times to the example period above, but I can't rule it out, either. I can imagine a scenario where the VM is put to sleep, and wakes up later, after the access token has expired. Rclone then continues to use it for a time (getting the indicated failures) until a new one is obtained.

The help I'm looking for is less around troubleshooting this specific example (though any help there is appreciated) and more about understanding when Rclone decides it needs a new access token in this scenario. I would think any failure like these would trigger Rclone to obtain a new token so no documents fail to copy.

2

Best bet is to put it debug log and collect a log and share the full debug log.

It refresh once per hour.

3

I can't share the entire log because it is confidential. I do have --log-level DEBUG enabled, and there are no log lines concerning obtaining a token. Do you happen to know if the token refresh is on a timer such that the following could occur?

  1. 01:00:00: Obtain initial access token
  2. 02:00:00: Obtain new access token
  3. 02:30:00: VM is paused
  4. 03:30:00: VM is resumed
  5. 04:00:00: Obtain new access token

If so, then this may explain my issue, as all attempts to copy documents between 03:30:00 and 04:00:00 would occur with the token obtained at 02:00:00, which is now invalid.

4

Without a log, it's a guessing game.

Decide if you want to redact things, PM me, PM ncw or whatnot but without a log, it's not possible to assist.

5

What I'm asking isn't tied to what is in the log, though. And there are no references to any tokens in the log.

6

I wish you the best of luck.

7

Could the time be wrong on the VM?

Rclone uses the time the token expires to know when to refresh it, so if the time is out that could explain the problem.

8

I think it's possible, yes. If Rclone will refresh the token based on the expiration time and not a static timer, I think that's the likely explanation. Thanks!

9

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