Nice!
Now have a command, test case and output.
I noticed that this pull request added it in: Add a json format log by justina777 · Pull Request #3373 · rclone/rclone · GitHub
@Justina @ncw
Here is the way to recreate as it does look like a bug to me:
I did:
dd if=/dev/zero of=file bs=1 count=10240000 & rclone sync file file-copy --use-json-log -vv --log-file /tmp/blah.log
which the log looks like:
felix@gemini:~$ cat /tmp/blah.log
{"level":"debug","msg":"Version \"v1.57.0\" starting with parameters [\"rclone\" \"sync\" \"file\" \"file-copy\" \"--use-json-log\" \"-vv\" \"--log-file\" \"/tmp/blah.log\"]","object":"rclone","objectType":"string","source":"cmd/cmd.go:408","time":"2021-11-03T14:08:28.630837-04:00"}
{"level":"debug","msg":"Creating backend with remote \"file\"","source":"fs/newfs.go:28","time":"2021-11-03T14:08:28.631014-04:00"}
{"level":"debug","msg":"Using config file from \"/opt/rclone/rclone.conf\"","source":"config/config.go:353","time":"2021-11-03T14:08:28.631087-04:00"}
{"level":"debug","msg":"fs cache: adding new entry for parent of \"file\", \"/home/felix\"","source":"cache/cache.go:86","time":"2021-11-03T14:08:28.631184-04:00"}
{"level":"debug","msg":"Creating backend with remote \"file-copy\"","source":"fs/newfs.go:28","time":"2021-11-03T14:08:28.631202-04:00"}
{"level":"debug","msg":"fs cache: renaming cache item \"file-copy\" to be canonical \"/home/felix/file-copy\"","source":"cache/cache.go:79","time":"2021-11-03T14:08:28.631281-04:00"}
{"level":"debug","msg":"Need to transfer - File not found at Destination","object":"file","objectType":"*local.Object","source":"operations/operations.go:1577","time":"2021-11-03T14:08:28.63132-04:00"}
{"level":"warning","msg":"Removing partially written file on error: can't copy - source file is being updated (size changed from 11102 to 11160)","object":"file","objectType":"*local.Object","source":"local/local.go:1202","time":"2021-11-03T14:08:28.631411-04:00"}
{"level":"error","msg":"Failed to copy: can't copy - source file is being updated (size changed from 11102 to 11160)","object":"file","objectType":"*local.Object","source":"operations/operations.go:509","time":"2021-11-03T14:08:28.631556-04:00"}
{"level":"error","msg":"Attempt 1/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 11102 to 11160)","source":"cmd/cmd.go:283","time":"2021-11-03T14:08:28.631589-04:00"}
{"level":"debug","msg":"Need to transfer - File not found at Destination","object":"file","objectType":"*local.Object","source":"operations/operations.go:1577","time":"2021-11-03T14:08:28.631613-04:00"}
{"level":"warning","msg":"Removing partially written file on error: can't copy - source file is being updated (size changed from 11247 to 11273)","object":"file","objectType":"*local.Object","source":"local/local.go:1202","time":"2021-11-03T14:08:28.631666-04:00"}
{"level":"error","msg":"Failed to copy: can't copy - source file is being updated (size changed from 11247 to 11273)","object":"file","objectType":"*local.Object","source":"operations/operations.go:509","time":"2021-11-03T14:08:28.631717-04:00"}
{"level":"error","msg":"Attempt 2/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 11247 to 11273)","source":"cmd/cmd.go:283","time":"2021-11-03T14:08:28.631736-04:00"}
{"level":"debug","msg":"Need to transfer - File not found at Destination","object":"file","objectType":"*local.Object","source":"operations/operations.go:1577","time":"2021-11-03T14:08:28.631761-04:00"}
{"level":"warning","msg":"Removing partially written file on error: can't copy - source file is being updated (size changed from 11327 to 11354)","object":"file","objectType":"*local.Object","source":"local/local.go:1202","time":"2021-11-03T14:08:28.63181-04:00"}
{"level":"error","msg":"Failed to copy: can't copy - source file is being updated (size changed from 11327 to 11354)","object":"file","objectType":"*local.Object","source":"operations/operations.go:509","time":"2021-11-03T14:08:28.63185-04:00"}
{"level":"error","msg":"Attempt 3/3 failed with 1 errors and: can't copy - source file is being updated (size changed from 11327 to 11354)","source":"cmd/cmd.go:283","time":"2021-11-03T14:08:28.63187-04:00"}
{"level":"info","msg":"\nTransferred: \t 0 B / 0 B, -, 0 B/s, ETA -\nErrors: 1 (retrying may help)\nElapsed time: 0.0s\n\n","source":"accounting/stats.go:480","stats":{"bytes":0,"checks":0,"deletedDirs":0,"deletes":0,"elapsedTime":0.0133494,"errors":1,"eta":null,"fatalError":false,"lastError":"can't copy - source file is being updated (size changed from 11327 to 11354)","renames":0,"retryError":true,"speed":0,"totalBytes":0,"totalChecks":0,"totalTransfers":0,"transferTime":0,"transfers":0},"time":"2021-11-03T14:08:28.631905-04:00"}
{"level":"debug","msg":"3 go routines active\n","source":"cmd/cmd.go:298","time":"2021-11-03T14:08:28.631941-04:00"}
2021/11/03 14:08:28 Failed to sync: can't copy - source file is being updated (size changed from 11327 to 11354)
felix@gemini:~$
