Help with stats logging

What is the problem you are having with rclone?

I don't understand the information presented with --stats-one-line-date.

What is your rclone version (output from rclone version)

rclone v1.55.1

  • os/type: windows
  • os/arch: amd64
  • go/version: go1.16.3
  • go/linking: dynamic
  • go/tags: cmount

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

Windows, 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)

rclone move Source: Target: --drive-server-side-across-configs --stats-one-line-date

The rclone config contents with secrets removed.

[Source]
type = drive
scope = drive
service_account_file = C:\Temp\key.json
impersonate = user@example.com

A log from the command with the -vv flag

I don't think the full log is useful here. I only have questions about the stats logging, which I'll post below. My questions:

  • I see files being moved, but the 0 in 0 / N GBytes never changes. What does this mean, and should it be showing progress? This presumably accounts for the 0% as well.

  • Why is no ETA shown?

  • What does xfr#0/N mean? If I had to guess, xfr# is short for transfer number, but it remains 0 even as I'm watching files being moved.

2021/06/26 11:36:10 INFO  : 2021/06/26 11:36:10 -          0 / 0 Bytes, -, 0 Bytes/s, ETA -
2021/06/26 11:37:12 INFO  : 2021/06/26 11:37:12 -          0 / 13.309 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/4670)
2021/06/26 11:38:12 INFO  : 2021/06/26 11:38:12 -          0 / 30.140 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/8588)
2021/06/26 11:39:12 INFO  : 2021/06/26 11:39:12 -          0 / 44.259 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:40:12 INFO  : 2021/06/26 11:40:12 -          0 / 44.583 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:41:12 INFO  : 2021/06/26 11:41:12 -          0 / 45.878 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:42:12 INFO  : 2021/06/26 11:42:12 -          0 / 45.622 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:43:12 INFO  : 2021/06/26 11:43:12 -          0 / 44.982 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:44:12 INFO  : 2021/06/26 11:44:12 -          0 / 60.307 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:45:12 INFO  : 2021/06/26 11:45:12 -          0 / 60.908 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:46:12 INFO  : 2021/06/26 11:46:12 -          0 / 60.971 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:47:12 INFO  : 2021/06/26 11:47:12 -          0 / 60.617 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:48:12 INFO  : 2021/06/26 11:48:12 -          0 / 60.926 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:49:12 INFO  : 2021/06/26 11:49:12 -          0 / 60.342 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:50:12 INFO  : 2021/06/26 11:50:12 -          0 / 59.962 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:51:12 INFO  : 2021/06/26 11:51:12 -          0 / 60.092 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:52:12 INFO  : 2021/06/26 11:52:12 -          0 / 60.546 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:53:12 INFO  : 2021/06/26 11:53:12 -          0 / 61.603 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:54:12 INFO  : 2021/06/26 11:54:12 -          0 / 61.985 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:55:12 INFO  : 2021/06/26 11:55:12 -          0 / 63.051 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:56:12 INFO  : 2021/06/26 11:56:12 -          0 / 64.045 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:57:12 INFO  : 2021/06/26 11:57:12 -          0 / 64.151 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 11:58:12 INFO  : 2021/06/26 11:58:12 -          0 / 71.966 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10007)
2021/06/26 11:59:12 INFO  : 2021/06/26 11:59:12 -          0 / 71.837 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10007)
2021/06/26 12:00:12 INFO  : 2021/06/26 12:00:12 -          0 / 71.990 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:01:12 INFO  : 2021/06/26 12:01:12 -          0 / 72.331 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:02:12 INFO  : 2021/06/26 12:02:12 -          0 / 73.158 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:03:12 INFO  : 2021/06/26 12:03:12 -          0 / 73.312 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:04:12 INFO  : 2021/06/26 12:04:12 -          0 / 73.060 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:05:12 INFO  : 2021/06/26 12:05:12 -          0 / 73.890 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:06:12 INFO  : 2021/06/26 12:06:12 -          0 / 74.619 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:07:12 INFO  : 2021/06/26 12:07:12 -          0 / 79.854 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:08:12 INFO  : 2021/06/26 12:08:12 -          0 / 88.799 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:09:12 INFO  : 2021/06/26 12:09:12 -          0 / 100.392 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:10:12 INFO  : 2021/06/26 12:10:12 -          0 / 99.125 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)
2021/06/26 12:11:12 INFO  : 2021/06/26 12:11:12 -          0 / 102.294 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/10008)

Hmm, it could be because you are doing a server-side move, then it is hard/impossible for rclone to know the progress and stats.

Are the stats OK, if you do this:

rclone check --download Target: Target: --stats-one-line-date --stats 5s

Thanks for the reply! Is using Target: for both remotes intentional or a typo? Can you elaborate on what this command is doing?

The check command with the --download flag does a bitwise compare of the files in Target: against the (same) files in Target:

The point is to perform something that will report stats without modifying your data. So yes it is very intentional to use the same remote twice - it can also be Source: if you prefer.

I did not get any stats when running the command as shown, but I did when adding -vv. Yes, it does seem to provide valid data in this case.

λ rclone check --download Test: Test: --stats-one-line-date --stats 1s
2021/06/27 16:31:10 NOTICE: Google drive root '': 2 differences found
2021/06/27 16:31:10 NOTICE: Google drive root '': 2 errors while checking
2021/06/27 16:31:10 NOTICE: Google drive root '': 14 matching files
2021/06/27 16:31:10 Failed to check with 2 errors: last error was: 2 differences found

λ rclone check --download Test: Test: --stats-one-line-date --stats 1s -vv
2021/06/27 16:31:18 DEBUG : Using config file from "C:\\Users\\Chad\\.config\\rclone\\rclone.conf"
2021/06/27 16:31:18 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "check" "--download" "Test:" "Test:" "--stats-one-line-date" "--stats" "1s" "-vv"]
2021/06/27 16:31:18 DEBUG : Creating backend with remote "Test:"
2021/06/27 16:31:19 DEBUG : Google drive root '': root_folder_id = "0AAdwwwP5yNO8Uk9PVA" - save this in the config to speed up startup
2021/06/27 16:31:19 DEBUG : Google drive root '': Waiting for checks to finish
2021/06/27 16:31:20 INFO  : 2021/06/27 16:31:20 -          0 / 108.694 kBytes, 0%, 0 Bytes/s, ETA -
2021/06/27 16:31:20 DEBUG : file-sample_100kB.docx: OK
2021/06/27 16:31:20 DEBUG : file-sample_100kB.doc: OK
2021/06/27 16:31:21 INFO  : 2021/06/27 16:31:21 -   573.389k / 3.494 MBytes, 16%, 380.635 kBytes/s, ETA 7s
2021/06/27 16:31:21 DEBUG : Google Doc 2 (Copy).docx: Updating size of doc after download to 6132
2021/06/27 16:31:21 DEBUG : Google Doc 2 (Copy).docx: Updating size of doc after download to 6132
2021/06/27 16:31:21 DEBUG : Google Doc 2 (Copy).docx: OK
2021/06/27 16:31:21 DEBUG : file-sample_500kB.doc: OK
2021/06/27 16:31:21 DEBUG : file-sample_500kB.docx: OK
2021/06/27 16:31:21 DEBUG : file-sample_1MB.doc: OK
2021/06/27 16:31:21 DEBUG : Google Doc 1 (Move).docx: Updating size of doc after download to 7080
2021/06/27 16:31:21 DEBUG : Google Doc 1 (Move).docx: Updating size of doc after download to 7080
2021/06/27 16:31:21 DEBUG : Google Doc 1 (Move).docx: OK
2021/06/27 16:31:21 DEBUG : file-sample_1MB.docx: OK
2021/06/27 16:31:22 INFO  : 2021/06/27 16:31:22 -     7.601M / 15.810 MBytes, 48%, 3.037 MBytes/s, ETA 2s
2021/06/27 16:31:22 DEBUG : file_example_MP3_2MG.mp3: OK
2021/06/27 16:31:23 INFO  : 2021/06/27 16:31:23 -    13.176M / 49.504 MBytes, 27%, 3.762 MBytes/s, ETA 9s
2021/06/27 16:31:23 DEBUG : file_example_MP3_1MG.mp3: OK
2021/06/27 16:31:24 DEBUG : file_example_MP4_480_1_5MG.mp4: OK
2021/06/27 16:31:24 INFO  : 2021/06/27 16:31:24 -    28.679M / 57.285 MBytes, 50%, 6.368 MBytes/s, ETA 4s
2021/06/27 16:31:24 DEBUG : file_example_MP3_700KB.mp3: OK
2021/06/27 16:31:25 INFO  : 2021/06/27 16:31:25 -    40.840M / 63.326 MBytes, 64%, 7.415 MBytes/s, ETA 3s
2021/06/27 16:31:25 DEBUG : file_example_MP4_640_3MG.mp4: OK
2021/06/27 16:31:26 INFO  : 2021/06/27 16:31:26 -    60.784M / 73.296 MBytes, 83%, 9.340 MBytes/s, ETA 1s
2021/06/27 16:31:26 DEBUG : file_example_MP4_1280_10MG.mp4: OK
2021/06/27 16:31:27 INFO  : 2021/06/27 16:31:27 -    71.557M / 78.681 MBytes, 91%, 9.534 MBytes/s, ETA 0s
2021/06/27 16:31:27 DEBUG : file_example_MP3_5MG.mp3: OK
2021/06/27 16:31:28 INFO  : 2021/06/27 16:31:28 -    83.650M / 84.725 MBytes, 99%, 9.834 MBytes/s, ETA 0s
2021/06/27 16:31:28 DEBUG : file_example_MP4_1920_18MG.mp4: OK
2021/06/27 16:31:28 NOTICE: Google drive root '': 0 differences found
2021/06/27 16:31:28 NOTICE: Google drive root '': 16 matching files
2021/06/27 16:31:28 INFO  : 2021/06/27 16:31:28 -    85.743M / 85.743 MBytes, 100%, 9.986 MBytes/s, ETA 0s
2021/06/27 16:31:28 DEBUG : 43 go routines active

Is there any way to get something approximating progress for the server-side case?

That is odd. I am using PowerShell, what are you using?

I typically use --progress --stats=5s.

I tried a server side copy on Google and that was OK. I also tried a server side move within the same account and it is almost instant, but didn't seem to be reflected in stats.

I therefore can't tell if it will help when you do a server side move between configs - it may?

I am using Cmder. I should mention I don't care so much about the progress of individual files, which as you say is quite fast because there is no download/upload. But I'm routinely dealing with remotes that have hundreds of thousands of files, and I need a way to track the progress of the job as a whole, which can run for many hours.

I've noticed that the second number (y) in xfr#x.y builds to a peak number early in the job and then falls. For example, these are the stat lines for the first handful of lines for a job that has been running for almost a day:

2021/06/27 12:03:34 INFO  : 2021/06/27 12:03:34 -          0 / 21.427 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/41788)
2021/06/27 12:04:34 INFO  : 2021/06/27 12:04:34 -          0 / 22.029 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/102920)
2021/06/27 12:05:34 INFO  : 2021/06/27 12:05:34 -          0 / 16.131 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/122604)
2021/06/27 12:06:34 INFO  : 2021/06/27 12:06:34 -          0 / 15.945 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/124818)
2021/06/27 12:07:34 INFO  : 2021/06/27 12:07:34 -          0 / 10.631 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/126996)
2021/06/27 12:08:34 INFO  : 2021/06/27 12:08:34 -          0 / 10.631 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/129110)
2021/06/27 12:09:34 INFO  : 2021/06/27 12:09:34 -          0 / 10.625 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/131347)
2021/06/27 12:10:34 INFO  : 2021/06/27 12:10:34 -          0 / 10.625 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/133535)
2021/06/27 12:11:34 INFO  : 2021/06/27 12:11:34 -          0 / 10.017 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/135746)
2021/06/27 12:12:34 INFO  : 2021/06/27 12:12:34 -          0 / 9.712 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/137933)
2021/06/27 12:13:34 INFO  : 2021/06/27 12:13:34 -          0 / 8.921 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/140152)
2021/06/27 12:14:34 INFO  : 2021/06/27 12:14:34 -          0 / 8.641 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/142267)
2021/06/27 12:15:34 INFO  : 2021/06/27 12:15:34 -          0 / 8.383 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/144493)
2021/06/27 12:16:34 INFO  : 2021/06/27 12:16:34 -          0 / 8.162 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/146686)
2021/06/27 12:17:34 INFO  : 2021/06/27 12:17:34 -          0 / 8.088 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/148920)
2021/06/27 12:18:34 INFO  : 2021/06/27 12:18:34 -          0 / 7.755 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/149373) <--- High-water mark
2021/06/27 12:19:34 INFO  : 2021/06/27 12:19:34 -          0 / 2.123 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/149217)
2021/06/27 12:20:34 INFO  : 2021/06/27 12:20:34 -          0 / 2.083 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/149105)
2021/06/27 12:21:34 INFO  : 2021/06/27 12:21:34 -          0 / 1.981 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/148950)

Once it reaches the high-water mark, it falls at a consistent rate for the remainder of the job. For example:

2021/06/27 13:21:34 INFO  : 2021/06/27 13:21:34 -          0 / 1.589 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/142242)
2021/06/27 14:21:34 INFO  : 2021/06/27 14:21:34 -          0 / 1.563 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/135617)
2021/06/27 15:21:34 INFO  : 2021/06/27 15:21:34 -          0 / 1.397 GBytes, 0%, 0 Bytes/s, ETA - (xfr#0/128787)
...
2021/06/28 03:21:23 INFO  : 2021/06/28 03:21:23 -          0 / 36.830 MBytes, 0%, 0 Bytes/s, ETA - (xfr#0/31969)
2021/06/28 04:21:23 INFO  : 2021/06/28 04:21:23 -          0 / 10.629 MBytes, 0%, 0 Bytes/s, ETA - (xfr#0/24599)
2021/06/28 05:21:23 INFO  : 2021/06/28 05:21:23 -          0 / 8.166 MBytes, 0%, 0 Bytes/s, ETA - (xfr#0/18477)

It seems to indicate the number of files remaining to move, but I'm not sure. If the high-water mark is the total number of files to be moved and each successive number is the remaining number of files to be moved, then we should be able to calculate a percentage to show in the stats. I'm not sure Rclone can recognize the high-water mark, though.

Very good observations! :ok_hand:

I have checked the code and found the following:

The xfr (=transfer) stats are formatted by this line:

It seems like the intention is to show the number of files transferred/moved sofar and the total number of files to be transferred (found sofar).

The total number of files to be transferred is calculated by this line:

You observed that this number increases while rclone finds the total number of files to be transferred, this probably corresponds to the transfer queue building up.

Then you observed that the number decreased in a consistent rate. This is most likely because the transferred queue decreasing for each file being transferred WITHOUT the file being added to the number of files transferred (s.transfers).

So it seems like there is a bug, where rclone misses an increment of s.transfers when doing a server-side transfer. There may be a similar bug for the total number of bytes transferred.

I was lucky in this search/analysis, but I do not have enough knowledge/time to find out where in the code to add the missing increments. I therefore suggest you create an issue and refer to this post.

I am sorry I cannot help you any further, but I am glad we managed to find a confirmed work around: The last number in the stats is indeed the number of files remaining (once the high water mark is passed) - until the bug is fixed :wink:

Thank you very much for the help! I have created an issue here: --stats-one-line-date does not increment transfers when doing a server-side move · Issue #5430 · rclone/rclone · GitHub.

1 Like

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