local: Rclone throwing "can't copy - source file is being updated" on Glusterfs

[TorPeeto]

Started on the forum and was asked to file this issue.

Have been using Rclone without issue to sync from a Gluster mounted drive to Dropbox for quite some time now, but have begun seeing the following in our logs:

ERROR : <filename>: Failed to copy: upload failed: Post https://content.dropboxapi.com/2/files/upload: can't copy - source file is being updated

This is not happening for all files, just some, and is very reproducible over many days/week for the same files.

rclone v1.40
- os/arch: linux/amd64
- go version: go1.10

Centos 7

The command being run is:

/usr/local/bin/rclone copy "/mnt/mnted_drive/" "dropbox:/<dir>/<dir>/" --max-age 3d --exclude "<term>*" >> /var/log/<log_name>

Only thing I can find in the error log is pasted above.

Along with the linked RClone forum post, I also found This

[TorPeeto]

As recommended in the forum post, I tried unmounting/remounting, no fix. I tried ls -l --full-time /path/to/problem/file repeatedly and see no changes. File size and modification times do not seem to be changing on the problematic files. They have been static for days, or a week, in some cases, but rclone still says the source is being written to.

[ncw]

When looking through the code I realised that it compares time.Time values with == not using the .Equal method.

Can you try this which corrects that and see if it fixes the problem?

https://beta.rclone.org/v1.40-040-g03912102-fix-2206/ (uploaded in 15-30 mins)

[TorPeeto]

Thanks for the help! Same issue after installing the beta version with your fix, however more detail that may help:

Failed to copy: upload failed: Post https://content.dropboxapi.com/2/files/upload: can't copy - source file is being updated (mod time changed from 2018-03-25 20:01:19.534 -0700 PDT to 2018-03-25 20:00:41.774 -0700 PDT), as an example. Others complaining in a similar fashion about time differences of as small as .03 seconds it looks like. The timestamps are mostly in the past, seemingly remaining static where they are. No active modification taking place on the file.

Tried the copy with --checksum and --size-only, no help.

[ncw]

I put that extra debug in to see if it printed anything interesting and it looks like it did!

Those two timestamps are 37.75s apart which is a long time...

Why do you think the timestamps have changed? Is it something to do with glusterfs?

Rclone is reading the timestamps using the fstat system call so reading the modification time of an open file handle.

Can you try this python program on one of the troublesome files and see if the mtime reported changes. Maybe while an rclone sync is running?

#!/usr/bin/python

import os
import sys
import time

if len(sys.argv) != 2:
    print "Syntax: %s <file>" % sys.argv[0]
    raise SystemExit(1)

name = sys.argv[1]

f = open(name, "rb")
fd = f.fileno()
while True:
    print os.fstat(fd).st_mtime
    time.sleep(1)

run it with python ./fstat_file.py /path/to/troublesome/file

[TorPeeto]

Yes, it looks like the mtime's change only while the sync is running. They remain static while no sync is running. Below are 2 examples; one is subtle while the other is more drastic. I started the sync before the python script, so you can see the mtime change only while the sync is running, and then change back after the sync is complete.

python ./fstat_file.py /path/to/troublesome/file/file.csv

1522774832.52
1522774832.52
1522774829.58
1522774832.52
1522774832.52
1522774832.52
1522774832.52
1522774832.52
1522774832.52

python ./fstat_file.py /path/to/troublesome/file/file.csv

1522033241.77
1522033241.77
1522033279.53
1522033279.53
1522033241.77
1522033241.77
1522033241.77
1522033241.77
1522033241.77

Unsure why the timestamps would change, or what is causing that. Ran some date commands on this node, other nodes with the gluster mounts, the gluster nodes, nothing seems very far off. Timestamps on these files appear to be static.

[ncw]

Yes, it looks like the mtime's change only while the sync is running.

I'm guessing that they might change if you do a find in the mount also instead of doing an rclone sync.

Unsure why the timestamps would change, or what is causing that

I don't know either... Either a bug in GlusterFS or the Linux kernel would be my suspicions, or possibly some kind of GlusterFS misconfiguration to do with time synchronization. I know almost nothing about GlusterFS though!

Have you got a GlusterFS expert you could ask?

[TorPeeto]

I will investigate Gluster more and report back here for closure. Thanks for the help.

[ncw]

Thanks - I'd be very interested to hear what you discover.

And if it turns out that you can't work around the problem, I can add a flag in rclone to skip those checks easily enough.

[janwout]

Looks like I possibly got the same issue, also using rclone sync on mount from glusterfs. In a docker container. Any advice for a workaround?