--check-first not working?

Suspected Bug
1

What is the problem you are having with rclone?

It seems like --check-first is not performing all checks before transfers start. In the log snippet, you can see that the number of transfers needed continues to grow after transfers have started. Shouldn't that total transfers needed number spool up to the final number before transfers start? In other words, shouldn't I see xfr#0/4162 before any transfers happen?

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

rclone v1.58.1
- os/version: Microsoft Windows 10 Pro 21H2 (64 bit)
- os/kernel: 10.0.19044.1706 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.17.9
- go/linking: dynamic
- go/tags: cmount

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

Google Drive -> Microsoft OneDrive

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

2022/06/01 13:03:55 DEBUG : rclone: Version "v1.58.1" starting with parameters ["C:\\Temp\\rclone.exe" "copy" "--check-first" "--checkers" "16" "--config" "C:\\Temp\\tmpC7CA.tmp" "--drive-skip-dangling-shortcuts" "--log-file" "C:\\Temp\\rclone.log" "--order-by" "size,mixed" "--retries" "1" "--stats" "5s" "--stats-one-line-date" "--transfers" "16" "--update" "--log-level" "DEBUG" "--create-empty-src-dirs" "Source:" "Target:"]

The rclone config contents with secrets removed.

[Source]
type = drive
scope = drive.readonly
service_account_file = C:\Temp\google.json
impersonate = user@example.org
[Target]
type = onedrive
client_id = ...
client_secret = ...
token = {"access_token":"...","token_type":"Bearer","refresh_token":"none","expiry":"2022-06-01T14:03:54.6561707-05:00"}
token_url = http://localhost:1976/m365/refreshTokenProxy
drive_id = ...
drive_type = business

A log from the command with the -vv flag

2022/06/01 13:03:56 INFO  : One drive root '': Running all checks before starting transfers
2022/06/01 13:04:01 INFO  : 2022/06/01 13:04:01 -           0 B / 1.146 GiB, 0%, 0 B/s, ETA - (xfr#0/658)
2022/06/01 13:04:06 INFO  : 2022/06/01 13:04:06 -           0 B / 1.390 GiB, 0%, 0 B/s, ETA - (xfr#0/924)
2022/06/01 13:04:11 INFO  : 2022/06/01 13:04:11 -           0 B / 2.440 GiB, 0%, 0 B/s, ETA - (xfr#0/1496)
2022/06/01 13:04:16 INFO  : 2022/06/01 13:04:16 -           0 B / 5.841 GiB, 0%, 0 B/s, ETA - (xfr#0/1812)
2022/06/01 13:04:21 INFO  : 2022/06/01 13:04:21 -           0 B / 6.649 GiB, 0%, 0 B/s, ETA - (xfr#0/2089)
2022/06/01 13:04:26 INFO  : 2022/06/01 13:04:26 -           0 B / 7.298 GiB, 0%, 0 B/s, ETA - (xfr#0/2257)
2022/06/01 13:04:31 INFO  : 2022/06/01 13:04:31 -           0 B / 9.012 GiB, 0%, 0 B/s, ETA - (xfr#0/2528)
2022/06/01 13:04:36 INFO  : 2022/06/01 13:04:36 -           0 B / 9.902 GiB, 0%, 0 B/s, ETA - (xfr#0/2650)
2022/06/01 13:04:41 INFO  : 2022/06/01 13:04:41 -           0 B / 10.369 GiB, 0%, 0 B/s, ETA - (xfr#0/2818)
2022/06/01 13:04:46 INFO  : 2022/06/01 13:04:46 -           0 B / 10.369 GiB, 0%, 0 B/s, ETA - (xfr#0/2818)
2022/06/01 13:04:51 INFO  : 2022/06/01 13:04:51 -           0 B / 10.369 GiB, 0%, 0 B/s, ETA - (xfr#0/2818)
2022/06/01 13:04:56 INFO  : 2022/06/01 13:04:56 -           0 B / 10.369 GiB, 0%, 0 B/s, ETA - (xfr#0/2818)
2022/06/01 13:05:01 INFO  : 2022/06/01 13:05:01 -    82.078 KiB / 10.369 GiB, 0%, 20.488 KiB/s, ETA 6d3h24m42s (xfr#0/2818)
2022/06/01 13:05:06 INFO  : 2022/06/01 13:05:06 -   174.078 KiB / 10.369 GiB, 0%, 9.105 KiB/s, ETA 1w6d19h40m25s (xfr#0/2818)
2022/06/01 13:05:11 INFO  : 2022/06/01 13:05:11 -    12.957 MiB / 10.369 GiB, 0%, 893.750 KiB/s, ETA 3h22m30s (xfr#12/2826)
2022/06/01 13:05:16 INFO  : 2022/06/01 13:05:16 -    34.839 MiB / 10.370 GiB, 0%, 1.806 MiB/s, ETA 1h37m39s (xfr#42/2846)
2022/06/01 13:05:21 INFO  : 2022/06/01 13:05:21 -    58.736 MiB / 10.372 GiB, 1%, 2.638 MiB/s, ETA 1h6m44s (xfr#87/2876)
2022/06/01 13:05:26 INFO  : 2022/06/01 13:05:26 -    78.043 MiB / 10.372 GiB, 1%, 2.989 MiB/s, ETA 58m47s (xfr#120/2898)
2022/06/01 13:05:31 INFO  : 2022/06/01 13:05:31 -   100.270 MiB / 10.372 GiB, 1%, 3.382 MiB/s, ETA 51m51s (xfr#156/2922)
2022/06/01 13:05:36 INFO  : 2022/06/01 13:05:36 -   121.779 MiB / 10.373 GiB, 1%, 3.647 MiB/s, ETA 47m59s (xfr#189/2944)
2022/06/01 13:05:41 INFO  : 2022/06/01 13:05:41 -   156.982 MiB / 10.398 GiB, 1%, 4.584 MiB/s, ETA 38m8s (xfr#225/2968)
2022/06/01 13:05:46 INFO  : 2022/06/01 13:05:46 -   180.952 MiB / 10.399 GiB, 2%, 4.617 MiB/s, ETA 37m47s (xfr#264/2994)
2022/06/01 13:05:51 INFO  : 2022/06/01 13:05:51 -   203.090 MiB / 10.399 GiB, 2%, 4.602 MiB/s, ETA 37m49s (xfr#303/3020)
2022/06/01 13:05:56 INFO  : 2022/06/01 13:05:56 -   222.432 MiB / 10.400 GiB, 2%, 4.404 MiB/s, ETA 39m27s (xfr#333/3040)
2022/06/01 13:06:01 INFO  : 2022/06/01 13:06:01 -   244.878 MiB / 10.401 GiB, 2%, 4.418 MiB/s, ETA 39m15s (xfr#369/3064)
2022/06/01 13:06:06 INFO  : 2022/06/01 13:06:06 -   267.851 MiB / 10.401 GiB, 3%, 4.475 MiB/s, ETA 38m40s (xfr#405/3088)
2022/06/01 13:06:11 INFO  : 2022/06/01 13:06:11 -   290.670 MiB / 10.402 GiB, 3%, 4.496 MiB/s, ETA 38m24s (xfr#447/3116)
2022/06/01 13:06:16 INFO  : 2022/06/01 13:06:16 -   311.157 MiB / 10.403 GiB, 3%, 4.390 MiB/s, ETA 39m15s (xfr#480/3138)
2022/06/01 13:06:21 INFO  : 2022/06/01 13:06:21 -   333.387 MiB / 10.404 GiB, 3%, 4.407 MiB/s, ETA 39m1s (xfr#519/3164)
2022/06/01 13:06:26 INFO  : 2022/06/01 13:06:26 -   355.547 MiB / 10.404 GiB, 3%, 4.424 MiB/s, ETA 38m47s (xfr#546/3182)
2022/06/01 13:06:31 INFO  : 2022/06/01 13:06:31 -   379.136 MiB / 10.404 GiB, 4%, 4.509 MiB/s, ETA 37m58s (xfr#582/3206)
2022/06/01 13:06:36 INFO  : 2022/06/01 13:06:36 -   406.938 MiB / 10.415 GiB, 4%, 4.845 MiB/s, ETA 35m17s (xfr#624/3234)
2022/06/01 13:06:41 INFO  : 2022/06/01 13:06:41 -   425.078 MiB / 10.415 GiB, 4%, 4.511 MiB/s, ETA 37m49s (xfr#648/3250)
2022/06/01 13:06:46 INFO  : 2022/06/01 13:06:46 -   441.746 MiB / 10.415 GiB, 4%, 4.200 MiB/s, ETA 40m34s (xfr#681/3272)
2022/06/01 13:06:51 INFO  : 2022/06/01 13:06:51 -   460.774 MiB / 10.416 GiB, 4%, 4.067 MiB/s, ETA 41m49s (xfr#723/3300)
2022/06/01 13:06:56 INFO  : 2022/06/01 13:06:56 -   482.320 MiB / 10.416 GiB, 5%, 4.151 MiB/s, ETA 40m53s (xfr#765/3328)
2022/06/01 13:07:01 INFO  : 2022/06/01 13:07:01 -   504.100 MiB / 10.417 GiB, 5%, 4.201 MiB/s, ETA 40m19s (xfr#807/3356)
2022/06/01 13:07:06 INFO  : 2022/06/01 13:07:06 -   526.001 MiB / 10.417 GiB, 5%, 4.244 MiB/s, ETA 39m49s (xfr#849/3384)
2022/06/01 13:07:11 INFO  : 2022/06/01 13:07:11 -   547.433 MiB / 10.417 GiB, 5%, 4.253 MiB/s, ETA 39m39s (xfr#894/3414)
2022/06/01 13:07:16 INFO  : 2022/06/01 13:07:16 -   566.191 MiB / 10.418 GiB, 5%, 4.130 MiB/s, ETA 40m45s (xfr#933/3440)
2022/06/01 13:07:21 INFO  : 2022/06/01 13:07:21 -   587.477 MiB / 10.418 GiB, 6%, 4.151 MiB/s, ETA 40m28s (xfr#975/3468)
2022/06/01 13:07:26 INFO  : 2022/06/01 13:07:26 -   608.644 MiB / 10.418 GiB, 6%, 4.170 MiB/s, ETA 40m12s (xfr#1014/3494)
2022/06/01 13:07:31 INFO  : 2022/06/01 13:07:31 -   632.429 MiB / 10.419 GiB, 6%, 4.340 MiB/s, ETA 38m32s (xfr#1059/3524)
2022/06/01 13:07:36 INFO  : 2022/06/01 13:07:36 -   656.182 MiB / 10.419 GiB, 6%, 4.455 MiB/s, ETA 37m27s (xfr#1107/3556)
2022/06/01 13:07:41 INFO  : 2022/06/01 13:07:41 -   679.877 MiB / 10.422 GiB, 6%, 4.539 MiB/s, ETA 36m41s (xfr#1143/3580)
2022/06/01 13:07:46 INFO  : 2022/06/01 13:07:46 -   698.363 MiB / 10.422 GiB, 7%, 4.316 MiB/s, ETA 38m30s (xfr#1185/3608)
2022/06/01 13:07:51 INFO  : 2022/06/01 13:07:51 -   718.359 MiB / 10.423 GiB, 7%, 4.214 MiB/s, ETA 39m22s (xfr#1227/3636)
2022/06/01 13:07:56 INFO  : 2022/06/01 13:07:56 -   732.562 MiB / 10.424 GiB, 7%, 3.852 MiB/s, ETA 43m (xfr#1266/3662)
2022/06/01 13:08:01 INFO  : 2022/06/01 13:08:01 -   752.971 MiB / 10.426 GiB, 7%, 3.841 MiB/s, ETA 43m3s (xfr#1314/3694)
2022/06/01 13:08:06 INFO  : 2022/06/01 13:08:06 -   778.680 MiB / 10.432 GiB, 7%, 4.253 MiB/s, ETA 38m48s (xfr#1338/3710)
2022/06/01 13:08:11 INFO  : 2022/06/01 13:08:11 -   800.731 MiB / 10.433 GiB, 7%, 4.293 MiB/s, ETA 38m21s (xfr#1386/3742)
2022/06/01 13:08:16 INFO  : 2022/06/01 13:08:16 -   822.035 MiB / 10.434 GiB, 8%, 4.285 MiB/s, ETA 38m21s (xfr#1428/3770)
2022/06/01 13:08:21 INFO  : 2022/06/01 13:08:21 -   840.818 MiB / 10.435 GiB, 8%, 4.154 MiB/s, ETA 39m29s (xfr#1470/3798)
2022/06/01 13:08:26 INFO  : 2022/06/01 13:08:26 -   855.685 MiB / 10.435 GiB, 8%, 3.834 MiB/s, ETA 42m43s (xfr#1506/3822)
2022/06/01 13:08:31 INFO  : 2022/06/01 13:08:31 -   877.475 MiB / 10.439 GiB, 8%, 3.973 MiB/s, ETA 41m9s (xfr#1533/3840)
2022/06/01 13:08:36 INFO  : 2022/06/01 13:08:36 -   899.994 MiB / 10.440 GiB, 8%, 4.135 MiB/s, ETA 39m27s (xfr#1560/3858)
2022/06/01 13:08:41 INFO  : 2022/06/01 13:08:41 -   922.504 MiB / 10.441 GiB, 9%, 4.204 MiB/s, ETA 38m43s (xfr#1590/3878)
2022/06/01 13:08:46 INFO  : 2022/06/01 13:08:46 -   943.044 MiB / 10.442 GiB, 9%, 4.200 MiB/s, ETA 38m41s (xfr#1626/3902)
2022/06/01 13:08:51 INFO  : 2022/06/01 13:08:51 -   967.409 MiB / 10.448 GiB, 9%, 4.388 MiB/s, ETA 36m57s (xfr#1662/3926)
2022/06/01 13:08:56 INFO  : 2022/06/01 13:08:56 -   988.269 MiB / 10.448 GiB, 9%, 4.365 MiB/s, ETA 37m4s (xfr#1695/3948)
2022/06/01 13:09:01 INFO  : 2022/06/01 13:09:01 -  1012.392 MiB / 10.448 GiB, 9%, 4.469 MiB/s, ETA 36m7s (xfr#1728/3970)
2022/06/01 13:09:06 INFO  : 2022/06/01 13:09:06 -     1.012 GiB / 10.450 GiB, 10%, 4.557 MiB/s, ETA 35m20s (xfr#1764/3994)
2022/06/01 13:09:11 INFO  : 2022/06/01 13:09:11 -     1.033 GiB / 10.451 GiB, 10%, 4.489 MiB/s, ETA 35m48s (xfr#1794/4014)
2022/06/01 13:09:16 INFO  : 2022/06/01 13:09:16 -     1.047 GiB / 10.451 GiB, 10%, 4.042 MiB/s, ETA 39m42s (xfr#1815/4028)
2022/06/01 13:09:21 INFO  : 2022/06/01 13:09:21 -     1.065 GiB / 10.452 GiB, 10%, 3.932 MiB/s, ETA 40m44s (xfr#1842/4046)
2022/06/01 13:09:26 INFO  : 2022/06/01 13:09:26 -     1.084 GiB / 10.452 GiB, 10%, 3.939 MiB/s, ETA 40m35s (xfr#1869/4064)
2022/06/01 13:09:31 INFO  : 2022/06/01 13:09:31 -     1.106 GiB / 10.452 GiB, 11%, 4.131 MiB/s, ETA 38m36s (xfr#1890/4078)
2022/06/01 13:09:36 INFO  : 2022/06/01 13:09:36 -     1.130 GiB / 10.454 GiB, 11%, 4.353 MiB/s, ETA 36m33s (xfr#1926/4102)
2022/06/01 13:09:41 INFO  : 2022/06/01 13:09:41 -     1.155 GiB / 10.460 GiB, 11%, 4.566 MiB/s, ETA 34m46s (xfr#1962/4126)
2022/06/01 13:09:46 INFO  : 2022/06/01 13:09:46 -     1.183 GiB / 10.475 GiB, 11%, 4.859 MiB/s, ETA 32m38s (xfr#1983/4140)
2022/06/01 13:09:51 INFO  : 2022/06/01 13:09:51 -     1.207 GiB / 10.477 GiB, 12%, 4.901 MiB/s, ETA 32m16s (xfr#2010/4158)
2022/06/01 13:09:56 INFO  : 2022/06/01 13:09:56 -     1.227 GiB / 10.477 GiB, 12%, 4.691 MiB/s, ETA 33m39s (xfr#2029/4162)
2

I suspect what you are seeing here are retries. Retries can add to the total sent bytes. If you run with -vv you can confirm.

3

Perhaps you can help me understand what is happening between these two stats lines:

2022/06/01 13:05:06 INFO  : 2022/06/01 13:05:06 -   174.078 KiB / 10.369 GiB, 0%, 9.105 KiB/s, ETA 1w6d19h40m25s (xfr#0/2818)
2022/06/01 13:05:11 INFO  : 2022/06/01 13:05:11 -    12.957 MiB / 10.369 GiB, 0%, 893.750 KiB/s, ETA 3h22m30s (xfr#12/2826)

I've been working off the understanding that xfr#0/2818 means that there are 2,818 transfers needed for this copy and 0 have occurred so far. And then in the next line, 2,826 transfers are needed, with 12 having occurred so far. Is this correct, or am I misunderstanding the log information?

Assuming my understanding is correct, it should mean that debug in between those statements will tell me why eight additional transfers were discovered to be needed while also showing the 12 transfers that occurred. I can't seem to piece it together, though.

2022/06/01 13:05:06 INFO  : 2022/06/01 13:05:06 -   174.078 KiB / 10.369 GiB, 0%, 9.105 KiB/s, ETA 1w6d19h40m25s (xfr#0/2818)
2022/06/01 13:05:07 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Starting multipart upload
2022/06/01 13:05:07 DEBUG : 1903090015 Roadrunner.docx: Starting multipart upload
2022/06/01 13:05:07 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Starting multipart upload
2022/06/01 13:05:07 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Uploading segment 0/7570 size 7570
2022/06/01 13:05:07 DEBUG : bugs.bunny@cartoons.org/WORKS DAL.docx: Starting multipart upload
2022/06/01 13:05:07 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Starting multipart upload
2022/06/01 13:05:07 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Uploading segment 0/8275 size 8275
2022/06/01 13:05:07 DEBUG : 1903090015 Roadrunner.docx: Uploading segment 0/9033 size 9033
2022/06/01 13:05:08 DEBUG : bugs.bunny@cartoons.org/WORKS DAL.docx: Uploading segment 0/6689 size 6689
2022/06/01 13:05:08 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Uploading segment 0/7459 size 7459
2022/06/01 13:05:08 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: quickxor = 9376b5a8cb7033f6a57b8b216dba4766e8b89311 OK
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Copied (new)
2022/06/01 13:05:08 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Updating size of doc after download to 7570
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Copied (Rcat, new)
2022/06/01 13:05:08 DEBUG : 1903090015 Roadrunner.docx: quickxor = 2536ffce57b2f2c5ab20246ef90569bfcc030f78 OK
2022/06/01 13:05:08 INFO  : 1903090015 Roadrunner.docx: Copied (new)
2022/06/01 13:05:08 DEBUG : 1903090015 Roadrunner.docx: Updating size of doc after download to 9033
2022/06/01 13:05:08 INFO  : 1903090015 Roadrunner.docx: Copied (Rcat, new)
2022/06/01 13:05:08 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: quickxor = 0cec8d7e9d021056a35e66cc5deb44098bd285b4 OK
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Copied (new)
2022/06/01 13:05:08 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Updating size of doc after download to 8275
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Copied (Rcat, new)
2022/06/01 13:05:09 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: quickxor = 56b811e98015e64f4caaf78d21f6986a408307de OK
2022/06/01 13:05:09 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Copied (new)
2022/06/01 13:05:09 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Updating size of doc after download to 7459
2022/06/01 13:05:09 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Copied (Rcat, new)
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (6479 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7172 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7903 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (9004 bytes), uploading instead of streaming
2022/06/01 13:05:10 DEBUG : daffy.duck@cartoons.org/City Council Meetings/2018/September 2018/Sept 17 2018/Agenda September 17 2018.docx: Starting multipart upload
2022/06/01 13:05:10 DEBUG : bugs.bunny@cartoons.org/Works／Daily wonderings and activities.docx: Starting multipart upload
2022/06/01 13:05:10 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905240020 NAR.docx: Starting multipart upload
2022/06/01 13:05:10 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905300004 NAR.docx: Starting multipart upload
2022/06/01 13:05:10 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905170005 Narrative.docx: Starting multipart upload
2022/06/01 13:05:10 DEBUG : Elmer Fudd.docx: Uploading segment 0/15937 size 15937
2022/06/01 13:05:10 DEBUG : daffy.duck@cartoons.org/2019-04-29 Hunter parking lot/20190429/20000700.sec: Uploading segment 0/213756242 size 10485760
2022/06/01 13:05:10 DEBUG : daffy.duck@cartoons.org/2019-04-29 Hunter parking lot/20190429/18250700.sec: Uploading segment 0/543437717 size 10485760
2022/06/01 13:05:10 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905300004 NAR.docx: Uploading segment 0/9004 size 9004
2022/06/01 13:05:10 DEBUG : daffy.duck@cartoons.org/City Council Meetings/2016/2016 Audios/P & Z 7-11-2016.MP3: Uploading segment 0/194707404 size 10485760
2022/06/01 13:05:10 DEBUG : minnie.mouse@cartoons.org/1A0005AD20190613142035/1A0005AD20190613142035001i100.avi: Uploading segment 0/967923652 size 10485760
2022/06/01 13:05:10 DEBUG : daffy.duck@cartoons.org/2019-04-29 Hunter parking lot/1129- City Hall MVC .MP4: Uploading segment 0/177663057 size 10485760
2022/06/01 13:05:10 DEBUG : 1912030004 Narrative.docx: Uploading segment 0/12275 size 12275
2022/06/01 13:05:11 DEBUG : daffy.duck@cartoons.org/City Council Meetings/2018/September 2018/Sept 17 2018/Agenda September 17 2018.docx: Uploading segment 0/16810 size 16810
2022/06/01 13:05:11 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905170005 Narrative.docx: Uploading segment 0/7903 size 7903
2022/06/01 13:05:11 DEBUG : daffy.duck@cartoons.org/2019-04-29 Hunter parking lot/20190429/18250000.bu: Uploading segment 0/542672144 size 10485760
2022/06/01 13:05:11 DEBUG : mickey.mouse@cartoons.org/Case Files-2019/1905240020 NAR.docx: Uploading segment 0/7172 size 7172
2022/06/01 13:05:11 DEBUG : daffy.duck@cartoons.org/Zoom Meetings/City Council Meeting 7-20-2020.mp4: Uploading segment 0/201160842 size 10485760
2022/06/01 13:05:11 DEBUG : bugs.bunny@cartoons.org/Works／Daily wonderings and activities.docx: Uploading segment 0/6479 size 6479
2022/06/01 13:05:11 INFO  : 2022/06/01 13:05:11 -    12.957 MiB / 10.369 GiB, 0%, 893.750 KiB/s, ETA 3h22m30s (xfr#12/2826)
4

I suspect that the problem is here.

I wonder if these are double counting the number of transfers.

I think it is something to do with the Google docs which rclone doesn't know those long they are.

What do you think? Does that add up?

5

That might explain the 12 transfers, which I guess are these?

2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Copied (new)
2022/06/01 13:05:08 INFO  : 1903090015 Roadrunner.docx: Copied (new)
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Copied (new)
2022/06/01 13:05:09 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Copied (new)

2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Copied (Rcat, new)
2022/06/01 13:05:08 INFO  : 1903090015 Roadrunner.docx: Copied (Rcat, new)
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Copied (Rcat, new)
2022/06/01 13:05:09 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Copied (Rcat, new)

2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (6479 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7172 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7903 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (9004 bytes), uploading instead of streaming

But I still don't know why the total transfer number increases from 2818 to 2826 when --check-first is enabled. Isn't that supposed to identify all of the transfers that need to happen before any transfers actually take place? To see it incrementing the total transfers required after transfers have begun is what has me confused.

Is it possible there are transfers that need to happen but that are not detectable when the checkers run? Could those eight additional transfers be these?

2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905110009 NAR.docx: Copied (Rcat, new)
2022/06/01 13:05:08 INFO  : 1903090015 Roadrunner.docx: Copied (Rcat, new)
2022/06/01 13:05:08 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120019／1905120020.docx: Copied (Rcat, new)
2022/06/01 13:05:09 INFO  : mickey.mouse@cartoons.org/Case Files-2019/1905120017 NAR.docx: Copied (Rcat, new)

2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (6479 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7172 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (7903 bytes), uploading instead of streaming
2022/06/01 13:05:09 DEBUG : One drive root '': File to upload is small (9004 bytes), uploading instead of streaming

If so, then the theory would be that the checking phase found these four files and added them to the total transfers number, before any transfers occurred. Then, during transfer, it was determined that these additional eight transfers were needed. So the transfers completed go up by 12 (the four transfers we knew about plus the eight we didn't) and total transfers needed go up by eight (the eight we didn't know were needed).

I'm just trying to make numbers add up. I have no idea what Copied (Rcat, new) means or why it is necessary.

6

It looks like each one of those unknown length files is counting as 3 (!) transfers. Here is a simple example

$ rclone -vv copy drive:GDocs/Sheets.xlsx /tmp/
...
Transferred:   	    7.078 KiB / 7.078 KiB, 100%, 0 B/s, ETA -
Transferred:            3 / 3, 100%
Elapsed time:         3.8s

I think this makes the maths add up, their being an additional 4 * 2 = 8 transfers.

The stats routines noticed that these 4 files got transferred 3 times each so it counted them as a retry for the second and third copy and increased the total for that.

No.

I think this is 100% a stats artifact!

Can you open a new issue on Github about this and I'll have a go at a fix. Thank you!

7

Done: Stats incorrect count retries · Issue #6213 · rclone/rclone (github.com).

Thanks!

1 Like
8

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