Server side copy, diferent logs; windows vs linux

asdffdsa · September 7, 2021, 6:10pm

What is the problem you are having with rclone?

for a server side copy, in the debug log

on windows, 269.394 MiByte/s
on linux, 0 Byte/s,

What is your rclone version (output from `rclone version`)

v1.56.0:
* win10 64bit
* termux on android phone
* ubuntu on raspberry pi4

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

aws s3

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

rclone copy aws:thesourcefolder aws:thedestfolder -vv --progress

The rclone config contents with secrets removed.

[aws]
type = s3
provider = AWS
access_key_id = 
secret_access_key = 
region = us-east-1
storage_class = STANDARD

A log from the command with the `-vv` flag

windows log

2021/09/07 13:29:22 DEBUG : Setting --config "C:\\data\\rclone\\scripts\\aws.conf" from environment variable RCLONE_CONFIG="C:\\data\\rclone\\scripts\\aws.conf"
2021/09/07 13:29:22 DEBUG : rclone: Version "v1.56.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone.exe" "copy" "aws:thesourcefolder" "aws:thedestfolder" "-vv" "--progress"]
2021/09/07 13:29:22 DEBUG : Creating backend with remote "aws:thesourcefolder"
2021/09/07 13:29:22 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\aws.conf"
2021/09/07 13:29:22 DEBUG : Creating backend with remote "aws:thedestfolder"
2021-09-07 13:29:22 DEBUG : S3 bucket thedestfolder: Waiting for checks to finish
2021-09-07 13:29:22 DEBUG : S3 bucket thedestfolder: Waiting for transfers to finish
2021-09-07 13:31:57 DEBUG : w10.21h1.iso: md5 = 9f1b5246902a6f1a12b9a03b97c732a8 OK
2021-09-07 13:31:57 INFO  : w10.21h1.iso: Copied (server-side copy)
Transferred:        4.243Gi / 4.243 GiByte, 100%, 269.394 MiByte/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:      2m35.2s

linux log, same output for termux on android and ubuntu on pi4

~ $ rclone copy aws:thesourcefolder aws:thedestfolder -vv --progress
2021/09/07 17:35:00 DEBUG : rclone: Version "1.56.0-termux" starting with parameters ["rclone" "copy" "aws:thesourcefolder" "aws:thedestfolder" "-vv" "--progress"]
2021/09/07 17:35:00 DEBUG : Creating backend with remote "aws:thesourcefolder"
2021/09/07 17:35:00 DEBUG : Using config file from "/data/data/com.termux/files/home/.config/rclone/rclone.conf"
2021/09/07 17:35:00 DEBUG : Creating backend with remote "aws:thedestfolder"
2021-09-07 17:35:00 DEBUG : S3 bucket thedestfolder: Waiting for checks to finish
2021-09-07 17:35:00 DEBUG : S3 bucket thedestfolder: Waiting for transfers to finish
2021-09-07 17:37:18 DEBUG : w10.21h1.iso: md5 = 9f1b5246902a6f1a12b9a03b97c732a8 OK
2021-09-07 17:37:18 INFO  : w10.21h1.iso: Copied (server-side copy)
Transferred:        4.243Gi / 4.243 GiByte, 100%, 0 Byte/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:      2m18.1s

Ole · September 24, 2021, 1:58pm

Hi Jojo,

I suspect that it is a coincidence.

I havent’t checked/tested (yet), but I guess rclone shows 0 Bytes/s as a replacement for indefinite, when the time is (almost) 0 seconds. It is just a simple hack we programmers often use to avoid fatal errors from division by zero.

It could be that the times ticks are longer on linux, or just pure coincidence.

asdffdsa · September 24, 2021, 3:12pm

hi,

sure, did my first /0 ERROR in 1978 on my trs-80.

if this was an intentional hack, then the behavior should be consistent.

been a while since i noticed it, so i will do more testing to narrow it down and post my results...

Ole · September 25, 2021, 11:00am

Sweet memories, it’s been a while since I soldered my own PC

Image source: https://nascom.wordpress.com/nascom/nascom-3-2/

This seems to be the average calculation used:

github.com

rclone/rclone/blob/1409b89f6c07d80bdfa880ad018a4a7771c049f1/fs/accounting/stats.go#L300-L334

    
      
          func (s *StatsInfo) averageLoop() {
          	var period float64
          
          
	ticker := time.NewTicker(averagePeriodLength)
          	defer ticker.Stop()
          
          
	startTime := time.Now()
          	a := &s.average
          	defer a.stopped.Done()
          	for {
          		select {
          		case now := <-ticker.C:
          			a.mu.Lock()
          			var elapsed float64
          			if a.lpTime.IsZero() {
          				elapsed = now.Sub(startTime).Seconds()
          			} else {
          				elapsed = now.Sub(a.lpTime).Seconds()
          			}
          			avg := 0.0

This file has been truncated. show original

It is the same across platforms and has the 0.0 in line 319.

asdffdsa · September 25, 2021, 4:28pm

very nice, z80, msbasic, light pen but could it zork?

tho i am not familiar with go syntax, rclone source code style and this is just a code snippet.
i am not seeing that
"It is just a simple hack we programmers often use to avoid fatal errors from division by zero."

line 319 is avg := 0.0
as i see it, with avg, no chance of a /0

avg is never used a divisor in a divide operation
the only other time avg is used is in an addition operation a.speed = (avg +

in fact, the only chance of /0, that i see is line 326.
period could be zero and there is no check on that.
that is not the case with line 320, where there is an explicit check to prevent a /0
if elapsed > 0

and even if i misinterpreted the source code and in fact, there is that /0 hack,
none of that explains the difference in reported speed in the test results from up above.

imho, this could be an issue with the display output, as there is another difference.
and as this is server side, no data is transfered, so the speed should be zero.

on windows 	ETA 0s
on linux	ETA -

i had planed to do some more testing, but i was a bad boy this morning.
so right now, i am in a time out, forced to watch the first episode of crapple's foundation series.
oh the horror of it all. if this is the end of me and i never post again in the forum, let this be a warning to all my beloved fellow rcloners.

Ole · September 25, 2021, 4:51pm

If the copy completes within 1 second then elapsed becomes zero:

github.com

rclone/rclone/blob/1409b89f6c07d80bdfa880ad018a4a7771c049f1/fs/accounting/stats.go#L313-L318

    
      
          			var elapsed float64
          			if a.lpTime.IsZero() {
          				elapsed = now.Sub(startTime).Seconds()
          			} else {
          				elapsed = now.Sub(a.lpTime).Seconds()
          			}

and this code makes sure rclone doesn't divide by elapsed (if zero), thus leaving avg=0:

github.com

rclone/rclone/blob/1409b89f6c07d80bdfa880ad018a4a7771c049f1/fs/accounting/stats.go#L319-L322

    
      
          			avg := 0.0
          			if elapsed > 0 {
          				avg = float64(a.lpBytes) / elapsed
          			}

asdffdsa · September 25, 2021, 5:09pm

well, that was fun...

hack or no hack, none of it addresses my issue.
that the output should be the same.

windows	linux
`269.394 MiByte/s`	`ETA 0s`
`0 Byte/s`	`ETA -`

Ole · September 26, 2021, 7:21am

OK, let’s be more systematic and collect some extra data.

What do you see if you execute this command on Windows and termux on android:

rclone copy aws:thesourcefolder aws:thedestfolder --ignore-times --stats 30s -vv

Does your WSL/Ubuntu produce the same output as the android and pi4?
(I vaguely remember you have it. If so then I have a possibility to confirm and debug)

system · November 26, 2021, 3:21am

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

Server side copy, diferent logs; windows vs linux

What is the problem you are having with rclone?

What is your rclone version (output from rclone version)

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

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

The rclone config contents with secrets removed.

A log from the command with the -vv flag

What is your rclone version (output from `rclone version`)

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

A log from the command with the `-vv` flag