Issue with rclone output starting from 1.50

What is the problem you are having with rclone?

When having output redirection like piping to tee, progress output gets duplicated on every stats update (once per second on my case). On older versions, the terminal was updated to have only the most recent stats update.

What is your rclone version (output from rclone version)

Issue happens on every version starting from v1.50, up to current beta, it does not happen up to v1.49.5.

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

Debian 10 (buster) 64-bit

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

Found the issue on Google Drive, however tried reproducing it on SFTP and it also happened. I think it's storage independent.

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

rclone copy server:copyfile . -P --stats 5s --bwlimit 7M | tee output

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

From affected version (v1.50):
username@hostname:~/rclonebug/rclone-v1.50.0-linux-amd64$ ./rclone -vv copy server:copyfile . --stats 1s | tee output
2020/04/21 01:37:44 DEBUG : rclone: Version "v1.50.0" starting with parameters ["./rclone" "-vv" "copy" "server:copyfile" "." "--stats" "1s"]
2020/04/21 01:37:44 DEBUG : Using config file from "/home1/username/.config/rclone/rclone.conf"
2020/04/21 01:37:46 DEBUG : sftp://root@server2:60022/copyfile: New connection xxx.xxx.xxx.xxx:33164->xxx.xxx.xxx.xxx:60022 to "SSH-2.0-OpenSSH_7.4p1 Debian-10+deb9u7"
2020/04/21 01:37:47 DEBUG : copyfile: Need to transfer - File not found at Destination
2020/04/21 01:37:48 INFO :
Transferred: 0 / 10 MBytes, 0%, 0 Bytes/s, ETA -
Errors: 0
Checks: 0 / 0, -
Transferred: 0 / 1, 0%
Elapsed time: 700ms
Transferring:

  •                                  copyfile:  0% /10M, 0/s, -
    

2020/04/21 01:37:49 INFO :
Transferred: 252k / 10 MBytes, 2%, 140.340 kBytes/s, ETA 1m11s
Errors: 0
Checks: 0 / 0, -
Transferred: 0 / 1, 0%
Elapsed time: 1.7s
Transferring:

  •                                  copyfile:  2% /10M, 59.986k/s, 2m46s
    

2020/04/21 01:37:50 INFO :
Transferred: 6.996M / 10 MBytes, 70%, 2.502 MBytes/s, ETA 1s
Errors: 0
Checks: 0 / 0, -
Transferred: 0 / 1, 0%
Elapsed time: 2.7s
Transferring:

  •                                  copyfile: 69% /10M, 510.012k/s, 6s
    

2020/04/21 01:37:51 DEBUG : sftp cmd = copyfile
2020/04/21 01:37:51 DEBUG : sftp output = "f1c9645dbc14efddc7d8a322685f26eb copyfile\n"
2020/04/21 01:37:51 DEBUG : sftp hash = "f1c9645dbc14efddc7d8a322685f26eb"
2020/04/21 01:37:51 DEBUG : copyfile: MD5 = f1c9645dbc14efddc7d8a322685f26eb OK
2020/04/21 01:37:51 INFO : copyfile: Copied (new)
2020/04/21 01:37:51 INFO :
Transferred: 10M / 10 MBytes, 100%, 2.716 MBytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 3.6s

2020/04/21 01:37:51 DEBUG : 13 go routines active
2020/04/21 01:37:51 DEBUG : rclone: Version "v1.50.0" finishing with parameters ["./rclone" "-vv" "copy" "server:copyfile" "." "--stats" "1s"]

From a non-affected version:
username@hostname:~/rclonebug/rclone-v1.49.5-linux-amd64$ ./rclone -vv copy server:copyfile . -P --stats 1s | tee output
2020/04/21 01:43:43 DEBUG : rclone: Version "v1.49.5" starting with parameters ["./rclone" "-vv" "copy" "server:copyfile" "." "-P" "--stats" "1s"]
2020/04/21 01:43:43 DEBUG : Using config file from "/home1/username/.config/rclone/rclone.conf"
2020/04/21 01:43:45 DEBUG : sftp://root@server2:60022/copyfile: New connection xxx.xxx.xxx.xxx:46966->xxx.xxx.xxx.xxx:60022 to "SSH-2.0-OpenSSH_7.4p1 Debian-10+deb9u7"
2020-04-21 01:43:46 DEBUG : copyfile: Couldn't find file - need to transfer
2020-04-21 01:43:49 DEBUG : copyfile: MD5 = f1c9645dbc14efddc7d8a322685f26eb OK
2020-04-21 01:43:49 INFO : copyfile: Copied (new)
Transferred: 10M / 10 MBytes, 100%, 2.811 MBytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 3.5s
2020/04/21 01:43:49 INFO :
Transferred: 10M / 10 MBytes, 100%, 2.811 MBytes/s, ETA 0s
Errors: 0
Checks: 0 / 0, -
Transferred: 1 / 1, 100%
Elapsed time: 3.5s

2020/04/21 01:43:49 DEBUG : 12 go routines active
2020/04/21 01:43:49 DEBUG : rclone: Version "v1.49.5" finishing with parameters ["./rclone" "-vv" "copy" "server:copyfile" "." "-P" "--stats" "1s"]

hello and welcome to the forum,

have you tried the flag
--stats-one-line

Hi,

Thanks for your reply. Same behaviour happens, just with less information:

username@hostname:~/rclonebug/rclone-v1.50.0-linux-amd64$ ./rclone copy server:copyfile . -P --stats 1s --stats-one-line | tee output
0 / 100 MBytes, 0%, 0 Bytes/s, ETA -252k / 100 MBytes, 0%, 140.708 kBytes/s, ETA 12m5s5.996M / 100 MBytes, 6%, 2.148 MBytes/s, ETA 43s14.996M / 100 MBytes, 15%, 3.956 MBytes/s, ETA 21s23.996M / 100 MBytes, 24%, 5.009 MBytes/s, ETA 15s33.996M / 100 MBytes, 34%, 5.871 MBytes/s, ETA 11s39.996M / 100 MBytes, 40%, 5.890 MBytes/s, ETA 10s48.996M / 100 MBytes, 49%, 6.289 MBytes/s, ETA 8s55.996M / 100 MBytes, 56%, 6.370 MBytes/s, ETA 6s64.996M / 100 MBytes, 65%, 6.638 MBytes/s, ETA 5s70.996M / 100 MBytes, 71%, 6.579 MBytes/s, ETA 4s80.996M / 100 MBytes, 81%, 6.869 MBytes/s, ETA 2s87.996M / 100 MBytes, 88%, 6.880 MBytes/s, ETA 1s93.996M / 100 MBytes, 94%, 6.816 MBytes/s, ETA 0s100M / 100 MBytes, 100%, 6.761 MBytes/s, ETA 0s100M / 100 MBytes, 100%, 6.593 MBytes/s, ETA 0s

While on v1.49.5, we have the stats updating:

username@hostname:~/rclonebug/rclone-v1.49.5-linux-amd64$ ./rclone copy server:copyfile . -P --stats 1s --stats-one-line | tee output
100M / 100 MBytes, 100%, 6.795 MBytes/s, ETA 0s

This gif should show the difference more clear than the log outputs: https://i.imgur.com/b3jS92a.gif

I think it's because of the stderr and stdout changes that got introduced at some point.

Your command is only capturing stdout and I think you want stderr too.

So append 2>&1 at the end of it.

Hi,

Thanks for your reply.

Same thing happens:

username@hostname:~/rclonebug/rclone-v1.50.0-linux-amd64$ rm copyfile; ./rclone copy server:copyfile . -P --stats 1s --bwlimit 7M 2>&1 | tee output
rm: cannot remove 'copyfile': No such file or directory
Transferred:   	      252k / 50 MBytes, 0%, 280.925 kBytes/s, ETA 3m1s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:       800ms
Transferring:
 *                                      copyfile:  0% /50M, 0/s, -Transferred:   	   10.059M / 50 MBytes, 20%, 5.302 MBytes/s, ETA 7s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        1.8s
Transferring:
 *                                      copyfile: 20% /50M, 1019.864k/s, 40sTransferred:   	   17.059M / 50 MBytes, 34%, 5.888 MBytes/s, ETA 5s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        2.8s
Transferring:
 *                                      copyfile: 34% /50M, 5.748M/s, 5sTransferred:   	   24.059M / 50 MBytes, 48%, 6.174 MBytes/s, ETA 4s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        3.8s
Transferring:
 *                                      copyfile: 48% /50M, 6.165M/s, 4sTransferred:   	   31.059M / 50 MBytes, 62%, 6.342 MBytes/s, ETA 2s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        4.8s
Transferring:
 *                                      copyfile: 62% /50M, 6.374M/s, 2sTransferred:   	   38.059M / 50 MBytes, 76%, 6.454 MBytes/s, ETA 1s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        5.8s
Transferring:
 *                                      copyfile: 76% /50M, 6.499M/s, 1sTransferred:   	   45.059M / 50 MBytes, 90%, 6.533 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        6.8s
Transferring:
 *                                      copyfile: 90% /50M, 6.583M/s, 0sTransferred:   	       50M / 50 MBytes, 100%, 6.332 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 1, 0%
Elapsed time:        7.8s
Transferring:
 *                                      copyfile:100% /50M, 6.642M/s, 0sTransferred:   	       50M / 50 MBytes, 100%, 6.236 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            1 / 1, 100%
Elapsed time:          8s

An example:

felix@gemini:~$ rclone lsf -vv GD: >> test.log 2>&1
felix@gemini:~$ cat test.log
2020/04/21 09:40:59 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "lsf" "-vv" "GD:"]
2020/04/21 09:40:59 DEBUG : Using config file from "/opt/rclone/rclone.conf"
blah.zip
crypt/
dslrcli-linux-amd64.zip
hosts
jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv
test/
2020/04/21 09:41:00 DEBUG : 5 go routines active
2020/04/21 09:41:00 DEBUG : rclone: Version "v1.51.0" finishing with parameters ["rclone" "lsf" "-vv" "GD:"]

I'm not sure offhand if pipes act differently as your piping it in. Will take a look though.

Interesting. Even this does the same thing.

rclone copy remote:file . -P --stats 1s --bwlimit 7M > >(tee -a stdout.log) 2> >(tee -a stderr.log >&2)

If you only redirect standarderr it works okay.
rclone copy remote:file . -P --stats 1s --bwlimit 7M 2> >(tee -a stderr.log >&2)

I'd probably open an issue on git for this.

Yes I can reproduce this.

A bit of git bisect reveals this to be the commit that introduced the problem

The problem can be fixed like this

diff --git a/lib/terminal/terminal.go b/lib/terminal/terminal.go
index 9a7c1ab7b..415247f49 100644
--- a/lib/terminal/terminal.go
+++ b/lib/terminal/terminal.go
@@ -74,7 +74,8 @@ func Start() {
                f := os.Stdout
                if !terminal.IsTerminal(int(f.Fd())) {
                        // If stdout not a tty then remove escape codes
-                       Out = colorable.NewNonColorable(f)
+                       //Out = colorable.NewNonColorable(f)
+                       Out = f
                } else if runtime.GOOS == "windows" && os.Getenv("TERM") != "" {
                        // If TERM is set just use stdout
                        Out = f

However this then outputs control characters to output which I think is undesirable.

Other commands, eg git log behave the same - if you pipe them to tee they lose their colouring.

I guess the options are

  • leave as it is
  • add a flag to stop the check for stdout being a terminal and default to do check
  • add a flag to stop the check for stdout being a terminal and default to don't check

If anyone could dig up any prior art from existing unix commands - what do they do?

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