Windows 10 - Rclone copies files over to mounted storage yet "failed to copy: chtimes: " error is displayed

Help and Support
1

What is the problem you are having with rclone?

Rclone is copying files/folders successfully in two different situations:

  1. Copies most files in a folder, while some are outputting errors
  2. Copies folders over the course of 2 tries/attempts

This happens when I try to copy larger folders >500MB in size of varying file types. Sometimes
it would be music (.flac, .mp3) or video (.mkv, .mp4), and other filetypes as well.

In the log file below I tried to upload a folder of .mkv videos, but the error can be replicated by uploading any other >500MB folders.

Tried following advice from this thread: Windows - local system mount permissions

Updated my WinFSP installation to the 2020 version, passed the flag "-o --UserName=nameofaccount" just in case I was running rclone as the system user but to no avail.

I've tried mounting it from a normal CMD window (which produces the same error) and using nssm to start rclone as a local service (using my windows credentials) and passed the following flags to nssm:

mount crypt-drive: Y: --config "X:\Users\aragane.config\rclone\rclone.conf" --vfs-cache-mode writes

The same error keeps popping up "Failed to copy: chtimes ..." but the upload completes with no visible problems with the files (I just did a quick pull from the mounted storage and opened the file in VLC, video plays fine). Could it be possible the way I passed the flags are wrongly formatted/typed? Would really appreciate your help solving this, cheers!

What is your rclone version (output from rclone version)

rclone v1.51.0

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

Windows 10 Build 1903
os/arch: windows/amd64

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

OneDrive Personal

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

rclone copy "X:/folder/some-folder" "Y:/new-folder/some-folder/" -P -vv

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

2020/04/15 20:11:48 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "copy" "X:/folder/some-folder" "Y:/new-folder/some-folder/" "-P" "-vv"]
2020/04/15 20:11:49 DEBUG : Using config file from "X:\Users\aragane\.config\rclone\rclone.conf"
2020-04-15 20:11:50 INFO : Local file system at //?/Y:/new-folder/some-folder/: Waiting for checks to finish
2020-04-15 20:11:50 INFO : Local file system at //?/Y:/new-folder/some-folder/: Waiting for transfers to finish
Transferred: 323.984M / 11.544 GBytes, 3%, 32.397 MBytes/s, ETA 5m54s
Transferred: 0 / 12, 0%
Elapsed time: 10.0s
Transferring:

  • file_xx_01.mkv: 6% /1.140G, 8.000M/s, 2m16s
  • file_xx_02.mkv: 6% /1016.387M, 6.224M/s, 2m33s
  • file_xx_03.mkv: 10% /915.516M, 9.389M/s, 1m27s
  • file_xx_04.mkv: 10% /916.859M, 10.663M/s, 1m16s
    X:\Users\aragane>rclone copy "X:/folder/some-folder" "Y:/new-folder/some-folder/" -P -vv --bwlimit 15M
    2020/04/15 20:12:21 DEBUG : rclone: Version "v1.51.0" starting with parameters ["rclone" "copy" "X:/folder/some-folder" "Y:/new-folder/some-folder/" "-P" "-vv" "--bwlimit" "15M"]
    2020/04/15 20:12:21 DEBUG : Using config file from "X:\Users\aragane\.config\rclone\rclone.conf"
    2020/04/15 20:12:21 INFO : Starting bandwidth limiter at 15MBytes/s
    2020-04-15 20:12:21 DEBUG : file_xx_01.mkv: Sizes differ (src 959988095 vs dst 98562048)
    2020-04-15 20:12:21 DEBUG : file_xx_03.mkv: Sizes differ (src 961396553 vs dst 104853504)
    2020-04-15 20:12:21 DEBUG : file_xx_04.mkv: Sizes differ (src 1223567911 vs dst 77590528)
    2020-04-15 20:12:21 INFO : Local file system at //?/Y:/new-folder/some-folder/: Waiting for checks to finish
    2020-04-15 20:12:21 DEBUG : file_xx_02.mkv: Sizes differ (src 1065758854 vs dst 69201920)
    2020-04-15 20:12:21 INFO : Local file system at //?/Y:/new-folder/some-folder/: Waiting for transfers to finish
    2020-04-15 20:18:03 ERROR : file_xx_07.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\07: The system cannot find the file specified.
    2020-04-15 20:18:07 DEBUG : file_xx_05.mkv: MD5 = 14a52ba3be07b1bc612605d29b154d0e OK
    2020-04-15 20:18:07 INFO : file_xx_05.mkv: Copied (new)
    2020-04-15 20:18:39 ERROR : file_xx_08.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\08: The system cannot find the file specified.
    2020-04-15 20:18:59 ERROR : file_xx_06.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\06: The system cannot find the file specified.
    2020-04-15 20:24:14 DEBUG : file_xx_10.mkv: MD5 = 290e418e72c3b857ce920f58c7027d67 OK
    2020-04-15 20:24:14 INFO : file_xx_10.mkv: Copied (new)
    2020-04-15 20:24:21 ERROR : file_xx_09.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\09: The system cannot find the file specified.
    2020-04-15 20:25:03 ERROR : file_xx_11.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\11: The system cannot find the file specified.
    2020-04-15 20:25:06 ERROR : file_xx_12.mkv: Failed to copy: chtimes \?\Y:\new-folder\some-folder\12: The system cannot find the file specified.
    2020-04-15 20:31:47 DEBUG : file_xx_01.mkv: MD5 = 7951e14ae59a6764fa423904c6c21f06 OK
    2020-04-15 20:31:47 INFO : file_xx_01.mkv: Copied (replaced existing)
    2020-04-15 20:31:50 DEBUG : file_xx_03.mkv: MD5 = dbc21592248ca1723c4e167b96a79955 OK
    2020-04-15 20:31:50 INFO : file_xx_03.mkv: Copied (replaced existing)
    2020-04-15 20:34:15 DEBUG : file_xx_02.mkv: MD5 = f4e9b504281567313334c595b3fd0ecd OK
    2020-04-15 20:34:15 INFO : file_xx_02.mkv: Copied (replaced existing)
    2020-04-15 20:36:23 DEBUG : file_xx_04.mkv: MD5 = e7948eeac97154a11191bf187fd95b51 OK
    2020-04-15 20:36:23 INFO : file_xx_04.mkv: Copied (replaced existing)
    2020-04-15 20:36:23 ERROR : Attempt 1/3 failed with 6 errors and: chtimes \?\Y:\new-folder\some-folder\12: The system cannot find the file specified.
    2020-04-15 20:36:23 INFO : Local file system at //?/Y:/new-folder/some-folder/: Waiting for checks to finish
    2020-04-15 20:36:23 DEBUG : file_xx_04.mkv: Modification times differ by -663.0803ms: 2020-04-15 17:51:08.6630803 +0800 +08, 2020-04-15 17:51:08 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_01.mkv: Modification times differ by -405.9595ms: 2020-04-15 17:50:23.4059595 +0800 +08, 2020-04-15 17:50:23 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_05.mkv: Modification times differ by -389.0768ms: 2020-04-15 17:51:45.3890768 +0800 +08, 2020-04-15 17:51:45 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_06.mkv: Modification times differ by 2h26m45.7669146s: 2020-04-15 17:52:13.2330854 +0800 +08, 2020-04-15 20:18:59 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_07.mkv: Modification times differ by 2h25m33.9158488s: 2020-04-15 17:52:28.0841512 +0800 +08, 2020-04-15 20:18:02 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_03.mkv: Modification times differ by -502.6724ms: 2020-04-15 17:50:42.5026724 +0800 +08, 2020-04-15 17:50:42 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_02.mkv: Modification times differ by -186.5218ms: 2020-04-15 17:50:28.1865218 +0800 +08, 2020-04-15 17:50:28 +0800 +08
    2020-04-15 20:36:23 DEBUG : file_xx_08.mkv: Modification times differ by 2h25m52.5224187s: 2020-04-15 17:52:46.4775813 +0800 +08, 2020-04-15 20:18:39 +0800 +08
2

hello and welcome to the forum,

you could try running rclone mounts as a service, using task scheduler or nssm.
and run it as system user, not your local username.
that is what i always do.

is X: a smb shared folder?

3

Hello asdffdsa!

Thanks for the quick reply, I did try running it as a system user before; Will give it a try again. Are the flags I passed to nssm all good?

Also, no, X: is not an smb shared folder. Should I make a shared folder and try copying from said folder to see if it produces the same error?

Cheers!

4

what is X: a local drive on your local computer?

5

Yessir it is a local hard drive. I have an SSD as a primary boot drive while X: serves as storage.

6

rclone is written in the Go language,

chtimes is a Go function
"Chtimes changes the access and modification times of the named file, similar to the Unix utime() or utimes() functions. "

there are two ways to run a command on the command line,

  1. running as your username wihtout administrator rights.
  2. running as your username with administrator rights.
    i would try running your command both ways and see what happens.
    if you run rclone as system user, then this not be a issue.
7

Thanks for the help so far @asdffdsa!

I've deleted the previous local service (as user service) and used nssm to create a new service (run as a system user). Running without hiccups for the time being, will post an update in the morning.

Currently running two jobs, one in a normal terminal, another running in an admin rights terminal. Both have not output the chtimes error yet, only a couple of I/O errors but that's alright.

I'm thinking maybe the folders' paths are too long and that's causing the chtimes error?

Cheers!

8

good,
i am curious that the upload/download speeds. i would imagine that you are geting very slow speeds.
you are running two copies of rclone.

  1. rclone mount
  2. rclone copy files to/from that rclone mount.

you could get much faster speds and more reliable copying by skipping the mount.
rclone copy X:/folder/some-folder crypt-drive:

9

@ncw, can you chtime in on this, err, i mean chime in?

10

The upload/download speeds are quite fast according to my standards /s.

Usually would get 40-50MB/s upload and 70-80MB/s down on a 500Mb/s plan in my country. Since we've been on lockdown for a while now the speeds tanked quite a bit.

I just realised what you said! Man, it might very well be because of me running two instances at the same time.

Will disable automatic startup of the mount and try running the command straight from cmd.

Thanks again!

11

Man oh man this forum seems pretty chill yo!

Tried uploading another folder with a longer path length, still waiting for the chtimes error to come haunt me again :stuck_out_tongue:

12

What this is, is rclone attempting to set the modification date of the file after it has been copied.

Is that exactly what the error message said? In particular does the path look correct in the error message?

It would be interesting to see the corresponding debug from the mount - I suspect it is a bug in the VFS layer of the mount, or at least a race condition.

13

Yep it's exactly what the previous errors have said too, all pointing to the destination folder I specified when running the command.

I'll try to obtain a full log file ASAP.

Cheers!

14

Pointing to the folder, not to a file? That is unexpected...

15

Aye I meant to say that the chtimes error would point to the file in the correct destination folder as specified, sorry for the confusion!

Also, would errors happen when certain characters are present in the filename? Examples of this would be square or curly brackets, parentheses etc. Might be worth noting that I've been using rclone for a while now, uploading and pulling files which have various naming schemes (spaces in between characters, special characters) from OneDrive.

Kinda weird how it suddenly bugged out and started outputting that error.

Edit: the problem was, as @asdffdsa pointed out earlier was that I was running two separate instances of rclone. Foregoing "rclone mount" as a service and using "rclone copy" straightaway is the way to go!

Edit 2: Was planning on mounting the encrypted drive for ease of access (drag 'n drop) from said drive to my local folders. Will be using a separate drive for this purpose instead. Leaving this here in case someone else tries the same setup :laughing:

Edit 3: Forgive my ignorance but as a layman I couldn't help but wonder if doing the following would be considered a race condition:

  1. rclone mount crypt-drive:
  2. rclone copy source:/folder crypt-drive:

Since @asdffdsa mentioned that running two instances would cause a dip in speeds. Might be the case that running two instances causes an R/W error/mishap someplace? Then leading to chtimes returning a "file not found" error.

Edit 4: Thanks for your time @ncw and @asdffdsa for such a trivial prob. Kudos to you both!

16

Yes I suspect it is some sort of timing issue.

For reasons I don't understand WinFSP seems a lot more prone to this sort of thing than FUSE on linux/macOS...