Possible bug in stats logs

Help and Support
1

Hello

I've noticed that stats's logs in the past was always like this (with 5 words Transferred, Errors, Checks, Transferred and Elapsed time)

=== PRIOR VERSIONS ===
2020/02/02 02:01:22 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/02 02:01:22 NOTICE: Serving remote control on http://[::]:5572/
2020/02/02 02:01:23 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 0
Checks:                 1 / 1, 100%
Transferred:            0 / 0, -
Elapsed time:          0s

In the version 1.51.0 I noticed that is not showing all words (only Transferred, Transferred and Elapsed time)

=== INFO ===
rclone copyto /etc/bacula/working/bacula.sql remote:/etc/bacula/working/bacula.sql --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui-no-open-browser  --log-file /tmp/logfile.log --log-level INFO
2020/02/10 14:28:11 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/10 14:28:11 NOTICE: Serving remote control on http://[::]:5572/
2020/02/10 14:29:25 INFO  : bacula.sql: Copied (new)
2020/02/10 14:29:25 INFO  :
Transferred:      453.327M / 453.327 MBytes, 100%, 6.279 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      1m12.1s



=== DEBUG ===
2020/02/10 14:31:59 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "copyto" "/etc/bacula/working/bacula.sql" "remote:/etc/bacula/working/bacula.sql" "--stats=1000m" "--rc" "--rc-addr" "0.0.0.0:5572" "--rc-user" "admin" "--rc-pass" "admin" "--rc-web-gui-no-open-browser" "--log-file" "/tmp/logfile.log" "--log-level" "DEBUG"]
2020/02/10 14:31:59 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/10 14:31:59 NOTICE: Serving remote control on http://[::]:5572/
2020/02/10 14:31:59 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/02/10 14:32:01 DEBUG : bacula.sql: Need to transfer - File not found at Destination
2020/02/10 14:32:01 DEBUG : bacula.sql: Starting multipart upload
2020/02/10 14:32:02 DEBUG : bacula.sql: Uploading segment 0/475347349 size 10485760
..... 
2020/02/10 14:33:24 DEBUG : bacula.sql: Uploading segment 471859200/475347349 size 3488149
2020/02/10 14:33:25 DEBUG : bacula.sql: SHA-1 = 2ceaa89546a3ae45a91e479a632418a948c4889d OK
2020/02/10 14:33:25 INFO  : bacula.sql: Copied (new)
2020/02/10 14:33:25 INFO  :
Transferred:      453.327M / 453.327 MBytes, 100%, 5.430 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      1m23.4s

2020/02/10 14:33:25 DEBUG : 7 go routines active
2020/02/10 14:33:25 DEBUG : rclone: Version "v1.51.0" finishing with parameters ["rclone" "copyto" "/etc/bacula/working/bacula.sql" "remote:/etc/bacula/working/bacula.sql" "--stats=1000m" "--rc" "--rc-addr" "0.0.0.0:5572" "--rc-user" "admin" "--rc-pass" "admin" "--rc-web-gui-no-open-browser" "--log-file" "/tmp/logfile.log" "--log-level" "DEBUG"]

Is it a bug or it was modified to be like this?

Thanks Wanderlei

2

It was a deliberate change to remove the 0 stats as we wanted to add more stats and the stats block got too long.

3

The main problem that is hard to identify in shell script if the file was transferred or not.

I used to use the second transferred word to read the number, if greater than 0 is because a file was transferred. Is there another way to identify this ?

2020/02/01 06:37:47 "rclone copyto /backup/disco02/Volume-VM-0024 remote:bacula/StorageLocal2/Volume-VM-0024  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui --log-file /var/log/bacula/wasabi.tmp --log-level INFO"
2020/02/01 06:37:47 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/01 06:37:47 NOTICE: Serving remote control on http://[::]:5572/
2020/02/01 06:45:35 INFO  : Volume-VM-0024: Copied (replaced existing)
2020/02/01 06:45:35 INFO  :
Transferred:        3.473G / 3.473 GBytes, 100%, 7.621 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            1 / 1, 100%
Elapsed time:     7m46.6s

2020/02/01 06:45:35 "rclone copyto /backup/disco02/Volume-VM-0025 remote:bacula/StorageLocal2/Volume-VM-0025  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui --log-file /var/log/bacula/wasabi.tmp --log-level INFO"
2020/02/01 06:45:35 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/01 06:45:35 NOTICE: Serving remote control on http://[::]:5572/
2020/02/01 06:45:37 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 0
Checks:                 1 / 1, 100%
Transferred:            0 / 0, -
Elapsed time:          0s

After 1.51.0 there's no pattern:

2020-02-11 02:00:02 "rclone sync /etc/bacula remote:bacula/etc/bacula  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui-no-open-browser --log-file /var/log/bacula/wasabi.tmp --log-level INFO --exclude *.pid --exclude *.state --exclude *.conmsg --exclude *.trace"
2020/02/11 02:00:02 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/11 02:00:02 NOTICE: Serving remote control on http://[::]:5572/
2020/02/11 02:00:09 INFO  : One drive root 'bacula-backup/etc/bacula': Waiting for checks to finish
2020/02/11 02:00:09 INFO  : One drive root 'bacula-backup/etc/bacula': Waiting for transfers to finish
2020/02/11 02:00:10 INFO  : bootstrap/Backup_VM_Servidor_AD.2020-02-10_23.55.00_59_Full_20398_srv_hyperv-fd.bsr: Copied (new)
2020/02/11 02:00:10 INFO  : bootstrap/Backup_VM_Servidor_R2D2.2020-02-10_23.55.01_00_Full_20399_srv_hyperv-fd.bsr: Copied (new)
2020/02/11 02:00:10 INFO  : bootstrap/Backup_VM_Servidor_Intranet.2020-02-10_23.55.00_58_Full_20397_srv_hyperv-fd.bsr: Copied (new)
2020/02/11 02:01:05 INFO  : working/bacula.sql: Copied (replaced existing)
2020/02/11 02:01:05 INFO  : Waiting for deletions to finish
2020/02/11 02:01:05 INFO  :
Transferred:      453.509M / 453.509 MBytes, 100%, 8.103 MBytes/s, ETA 0s
Checks:               175 / 175, 100%
Transferred:            4 / 4, 100%
Elapsed time:        55.9s

2020/02/11 02:01:05 "rclone copyto /backup/disco01/Volume-Diario-0001 remote:bacula/StorageLocal1/Volume-Diario-0001  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui-no-open-browser --log-file /var/log/bacula/wasabi.tmp --log-level INFO"
2020/02/11 02:01:05 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/11 02:01:05 NOTICE: Serving remote control on http://[::]:5572/
2020/02/11 02:01:06 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:         0.0s

2020/02/11 02:01:06 "rclone copyto /backup/disco01/Volume-Diario-0002 remote:bacula/StorageLocal1/Volume-Diario-0002  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui-no-open-browser --log-file /var/log/bacula/wasabi.tmp --log-level INFO"
2020/02/11 02:01:06 INFO  : Using --user admin --pass XXXX as authenticated user
2020/02/11 02:01:06 NOTICE: Serving remote control on http://[::]:5572/
2020/02/11 02:09:25 INFO  : Volume-Diario-0002: Copied (replaced existing)
2020/02/11 02:09:25 INFO  :
Transferred:        3.725G / 3.725 GBytes, 100%, 7.675 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      8m17.0s
4

There will always be a log like this when something is transferred.

With 1.51 if the exit code is 0 and the Transferred: is missing then all is OK.

Maybe another flag --stats-show-zeros or something like that could be implemented?

5

Hello Nick!

I guess every execution well succeeded will be return 0 (even a transfer occurs or not), but the problem is that have 2 exact words "Transferred" that difficult to identify a pattern.
Would not be better keep all information from stats by default ?

6

Identifying patterns isn't a great solution in general.. What if you had a file called "Transferred"?

The stats blocks are for humans...

However I'd be open to a --stats-show-zeros flag if you want to make a new issue on github about it?

7

Identifying patterns isn't a great solution in general.. What if you had a file called "Transferred"?

I know that isn't a good solution, but the rclone stats are this way and in the versions before 1.51.0, all stats always had the same 4 lines with the same informations:
Transferred, Checks, Transferred and Elapsed time:

Transferred:      453.509M / 453.509 MBytes, 100%, 8.103 MBytes/s, ETA 0s
Checks:               175 / 175, 100%
Transferred:            4 / 4, 100%
Elapsed time:        55.9s

The stats blocks are for humans...

How to get this information for machine reading ?

However I'd be open to a --stats-show-zeros flag if you want to make a new issue on github about it?
[/quote]
OK I can open a github issue. But why not invert the meaning of the flag, and show every information by default and create a flag --stats-not-show-zeros

The stats would be easier to read if they would be something like this (every kind of information in a separate line and more detailed:

Transferred Bytes:    453.509M / 453.509 MBytes, 100%, ETA 0s
Average Speed:        8.103 MBytes/s
Checks:                    175 / 175, 100%
Transferred Files:     4 / 4, 100%
Elapsed time:           55.9s

Thanks

8

Just a thought, but can't this be accomplished by using the rc function core/stats?

https://rclone.org/rc/#core/stats

9

The main reason is that I wanted to add more stats, Deleted being one of them, and I considered there were too many lines in the stats blocks.

That would work.

Another idea would be to use --use-json-log which makes the logs properly machine parseable, and then implement the idea of adding fields into the stats logs which are the value of the statistics so they don't have to be parsed from the log.

10

The way that I've tried to use --use-json-log it looks not so parsable.
There's no key that is possible to identify that is stats.
And the string that is the stats contains a lot of dirty like (too much spaces, line break character, tabulation character, etc)

{"level":"info","msg":"\nTransferred:   \t         0 / 0 Bytes, -, 0 Bytes/s, ETA -\nChecks:                 1 / 1, 100%\nElapsed time:         0.0s\n\n","source":"accounting/stats.go:368","time":"2020-02-12T07:44:46.293759-03:00"}

Would be better if the json log was something like this:

 {
     "level": "info",
     "msg": {
         "stats": {
             "Transferred Bytes": "453.509M / 453.509 MBytes, 100%, 8.103 MBytes/s, ETA 0s",
             "Checks": "175 / 175, 100%",
             "Transferred Files": "4 / 4, 100%",
             "Elapsed Time": "55.9s"
         }
     },
     "source": "accounting/stats.go:368",
     "time": "2020-02-11T09:00:33.753218-03:00"
 }

I've take a look in the core/stats and it looks have more information, but I don't know how to use.
The command that I'm using is below:

rclone copyto /etc/bacula/bacula-dir.conf remote:/etc/bacula/bacula-dir.conf  --stats=1000m --rc --rc-addr 0.0.0.0:5572 --rc-user admin --rc-pass admin --rc-web-gui-no-open-browser  --log-file /tmp/debug.log --use-json-log --log-level INFO

There is a way to return a json like this with the stats modifying the command above?

{
    "speed": average speed in bytes/sec since start of the process,
    "bytes": total transferred bytes since the start of the process,
    "errors": number of errors,
    "fatalError": whether there has been at least one FatalError,
    "retryError": whether there has been at least one non-NoRetryError,
    "checks": number of checked files,
    "transfers": number of transferred files,
    "deletes" : number of deleted files,
    "elapsedTime": time in seconds since the start of the process,
    "lastError": last occurred error,
    "transferring": an array of currently active file transfers:
        [
            {
                "bytes": total transferred bytes for this file,
                "eta": estimated time in seconds until file transfer completion
                "name": name of the file,
                "percentage": progress of the file transfer in percent,
                "speed": speed in bytes/sec,
                "speedAvg": speed in bytes/sec as an exponentially weighted moving average,
                "size": size of the file in bytes
            }
        ],
    "checking": an array of names of currently active file checks
        []
}
11

Yes it needs work to be useful, but it is probably worth doing.

The optimim way probably would be to run rclone rcd instead of copyto, then run a copyto job via the rc. You can then read the stats with the rc and shut down rclone when done. If you are doing multiple copytos then this will be more efficient than launching rclone each time.

12

Hello Nick!

Thanks for the answer, but unfortunately I didn't understand how to use. I read the documentation and I still can't understand.

Can you give me some example how to use?

13

Sure

First run

rclone rcd --rc-no-auth # maybe add auth here

To do an rclone copyto do something like this

rclone rc operations/copyfile srcFs= srcRemote=/etc/bacula/bacula-dir.conf dstfs:remote: dstRemote=/etc/bacula/bacula-dir.conf

To see the stats

rclone rc core/stats

You can also start a job by providing the _async flag and poll the stats just for that job.

14

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