JSON log incorrect transfer speed

Suspected Bug
1

What is the problem you are having with rclone?

The json log file contains incorrect transfer speed.

Here's an example:

{"time":"2025-06-23T12:18:43.1847001-06:00","level":"info","msg":"Copied (new)","size":4363308902,"object":"Files-Hourly.7z","objectType":"*local.Object","source":"slog/logger.go:256"} {"time":"2025-06-23T12:18:43.1863087-06:00","level":"info","msg":"\nTransferred: \t 4.064 GiB / 4.064 GiB, 100%, 1.379 MiB/s, ETA 0s\nTransferred: 1 / 1, 100%\nElapsed time: 12m4.6s\n\n","stats":{"bytes":4363308902,"checks":0,"deletedDirs":0,"deletes":0,"elapsedTime":724.6629689,"errors":0,"eta":0,"fatalError":false,"listed":0,"renames":0,"retryError":false,"serverSideCopies":0,"serverSideCopyBytes":0,"serverSideMoveBytes":0,"serverSideMoves":0,"speed":1446185.0205711238,"totalBytes":4363308902,"totalChecks":0,"totalTransfers":1,"transferTime":724.6327254,"transfers":1},"source":"slog/logger.go:256"}

My math shows 4,363,308,902 bytes over 724 seconds is 5.74MB/s, and the log shows 1.379 MiB/s. (I realize there is some difference between MiB and MB, but not this much!)

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

rclone v1.70.1

  • os/version: Microsoft Windows Server 2022 Standard 21H2 21H2 (64 bit)
  • os/kernel: 10.0.20348.3807 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.24.4
  • go/linking: static
  • go/tags: cmount

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

Not cloud. Transferring to 'SFTPGo 2.6.6 6825db76' running in a Ubuntu Linux virtual machine.

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

rclone copyto -v --use-json-log --log-file=helios-push.json --progress arhives\%FN% helios:%TARGETPATH%/%FN%

Note that %VALUES% are windows environment variables. This script is called by several backup processes, defining the source and target files.

The rclone config contents with secrets removed.

[helios]
type = sftp
host = 
user = 
port = [non standard]
pass = 
use_insecure_cipher = false
shell_type = unix
md5sum_command = md5sum
sha1sum_command = sha1sum

A log from the command with the -vv flag

{"time":"2025-06-23T12:39:16.0819022-06:00","level":"debug","msg":"Version \"v1.70.1\" starting with parameters [\"c:\\\\rclone\\\\rclone\" \"copyto\" \"-vv\" \"--use-json-log\" \"--log-file=helios-push.json\" \"--progress\" \"c:\\\\backup\\\\archives\\\\All-WWW-VS1-Files-Hourly.7z\" \"helios:/Daily-Important-Sync/DNN_VS1/test.7z\"]","object":"rclone","objectType":"string","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.0829028-06:00","level":"debug","msg":"Creating backend with remote \"Files-Hourly.7z\"","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.0839024-06:00","level":"debug","msg":"Using config file from \"rclone.conf\"","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.0839024-06:00","level":"debug","msg":"fs cache: renaming child cache item \"Files-Hourly.7z\" to be canonical for parent \"//?/archives\"","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.0839024-06:00","level":"debug","msg":"Creating backend with remote \"helios:/VS1/\"","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.4269364-06:00","level":"debug","msg":"New connection []:56148->[]:xxxx to \"SSH-2.0-SFTPGo_2.6.6\"","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.5947816-06:00","level":"debug","msg":"Shell type \"unix\" from config","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.5947816-06:00","level":"debug","msg":"Using root directory \"VS1/\"","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:39:16.6525855-06:00","level":"debug","msg":"Need to transfer - File not found at Destination","object":"Files-Hourly.7z","objectType":"*local.Object","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:40:16.709249-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:41:16.7142706-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:42:16.7198207-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:43:16.7247911-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:44:16.7305344-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:45:16.7362323-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:46:16.7419167-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:47:16.7471896-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:48:16.7529344-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:49:16.7579031-06:00","level":"debug","msg":"Not closing 0 unused connections as 1 sessions active","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:04.953003-06:00","level":"debug","msg":"Shell path \"/test.7z.a637260d.partial\"","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:05.0060351-06:00","level":"debug","msg":"Running remote command: md5sum test.7z.a637260d.partial","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:47.8187534-06:00","level":"debug","msg":"Remote command result: daceb6b8aae2fd7a3ac318c5b7f62c3a  test.7z.a637260d.partial","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:47.8187534-06:00","level":"debug","msg":"Parsed hash: daceb6b8aae2fd7a3ac318c5b7f62c3a","object":"test.7z.a637260d.partial","objectType":"*sftp.Object","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:47.8192896-06:00","level":"debug","msg":"md5 = daceb6b8aae2fd7a3ac318c5b7f62c3a OK","object":"Files-Hourly.7z","objectType":"*local.Object","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:48.4051872-06:00","level":"debug","msg":"renamed to: test.7z","object":"test.7z.a637260d.partial","objectType":"*sftp.Object","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:48.4051872-06:00","level":"info","msg":"Copied (new) to: test.7z","size":4363308902,"object":"Files-Hourly.7z","objectType":"*local.Object","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:48.4078446-06:00","level":"info","msg":"\nTransferred:   \t    4.064 GiB / 4.064 GiB, 100%, 302.444 KiB/s, ETA 0s\nTransferred:            1 / 1, 100%\nElapsed time:     11m31.6s\n\n","stats":{"bytes":4363308902,"checks":0,"deletedDirs":0,"deletes":0,"elapsedTime":691.6979726,"errors":0,"eta":0,"fatalError":false,"listed":0,"renames":0,"retryError":false,"serverSideCopies":0,"serverSideCopyBytes":0,"serverSideMoveBytes":0,"serverSideMoves":0,"speed":309703.1977425717,"totalBytes":4363308902,"totalChecks":0,"totalTransfers":1,"transferTime":691.6963843,"transfers":1},"source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:48.408383-06:00","level":"debug","msg":"12 go routines active\n","source":"slog/logger.go:256"}
{"time":"2025-06-23T12:50:48.4088926-06:00","level":"debug","msg":"Closing 1 unused connections","object":"sftp://VS1/","objectType":"*sftp.Fs","source":"slog/logger.go:256"}

I watched this run from the command line, and the reported transfer speed listed here in the log is the last transfer speed listed on the screen as the transfer completed. It clearly is not the division of total bytes by total time.

2

hi, is this a new problem, that started after updating rclone or a new first time issue?

3

I suspect it's always been there that I've used it (about a year, give or take).

Today I decided to look closely at the parsed output of the log as the reported speed to this one destination didn't look correct.

I then found the rclone version was about 1 year behind. I upgraded it to the current version, and it has the same behavior.

4

Do the speeds look correct while the transfer is running? You should test stats logs every 1 minute by default.

I think the speed may show the current instantaneous speed (averaged a bit).

5

I believe so, yes, until the end. As I've seen others note, after it appears the transfers end, it can "sit there" for quite some time, appearing to do nothing. Meanwhile the avg transfer speed decreases, as there are no more bytes to transfer, but time is still passing. As if it's doing CRC checks or some sort of data validation?

I say "I believe so" because I have it all scripted to push files at night in the off hours from "main sites" to "backup repositories". Very rarely do I actually watch the transfers, except for manual testing.

I parse the output of the json into a table for future review, which is how I realized the logged transfer speed is incorrect.

I've since changed the routine that displays the data on a web front end to do the math itself of total bytes / total time, which gives an accurate depiction of true transfer speed.

6

What is happening in the pause, is that rclone is running md5sum remote_file on the sftp server. This can take some time - hence the pause, but it allows rclone to double check the file transfer was intact.

You can disable the checksum if you want - from the docs

Disabling the checksumming may be required if you are connecting to SFTP servers which are not under your control, and to which the execution of remote shell commands is prohibited. Set the configuration option disable_hashcheck to true to disable checksumming entirely, or set shell_type to none to disable all functionality based on remote shell command execution.

7

Right, I surmised it was something like that. My point is, when watching it work, the "avg transfer speed" drops while the check is occurring, and the final speed reported in the log seems to be related to that speed. However, simple math from the values in the log differ from the speed reported in the log. Hence this post. :slight_smile: