New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
TorPeeto opened this Issue Apr 4, 2018 · 17 comments

Comments

Projects
None yet
4 participants
@TorPeeto

TorPeeto commented Apr 4, 2018

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

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 4, 2018

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.

TorPeeto commented Apr 4, 2018

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 added a commit that referenced this issue Apr 4, 2018

local: fix spurious can't copy - source file is being updated - fixes #…
…2206

This was caused by using == to compare time.Time values rather than
time.Time.Equal.

Update all the time comparisons to use .Equal.
@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Apr 4, 2018

Owner

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)

Owner

ncw commented Apr 4, 2018

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)

@ncw ncw added the bug label Apr 4, 2018

@ncw ncw added this to the v1.41 milestone Apr 4, 2018

@TorPeeto

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 4, 2018

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.

TorPeeto commented Apr 4, 2018

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.

@TorPeeto TorPeeto closed this Apr 4, 2018

@TorPeeto TorPeeto reopened this Apr 4, 2018

@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Apr 5, 2018

Owner

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

Owner

ncw commented Apr 5, 2018

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

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 5, 2018

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.

TorPeeto commented Apr 5, 2018

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 added a commit that referenced this issue Apr 5, 2018

local: work on spurious "can't copy - source file is being updated" e…
…rrors #2206

Update all the time comparisons to use time.Time.Equal instead of ==

Improve the logging for that error so we can see exactly what has changed
@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Apr 5, 2018

Owner

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?

Owner

ncw commented Apr 5, 2018

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

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 5, 2018

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

TorPeeto commented Apr 5, 2018

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

@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Apr 5, 2018

Owner

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.

Owner

ncw commented Apr 5, 2018

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

This comment has been minimized.

Show comment
Hide comment
@janwout

janwout Apr 6, 2018

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?

janwout commented Apr 6, 2018

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?

@TorPeeto

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 6, 2018

I had to put this down for a little bit, but the only other lead I have right now came from the stat command. My setup is 2 Gluster Nodes, that have the glusterfs mounted drives mounted on them. The drives are also mounted on another node for other purposes - this is the node where I am encountering the RClone error. What I found when running a stat on one of the problematic files from all 3 nodes, is that the mtime is identical on the "other purposes" node as well as one of the gluster nodes, but is different on the 2nd Gluster node. Workaround for now is manually moving certain files to where they need to be...

TorPeeto commented Apr 6, 2018

I had to put this down for a little bit, but the only other lead I have right now came from the stat command. My setup is 2 Gluster Nodes, that have the glusterfs mounted drives mounted on them. The drives are also mounted on another node for other purposes - this is the node where I am encountering the RClone error. What I found when running a stat on one of the problematic files from all 3 nodes, is that the mtime is identical on the "other purposes" node as well as one of the gluster nodes, but is different on the 2nd Gluster node. Workaround for now is manually moving certain files to where they need to be...

@ncw ncw changed the title from Rclone throwing "can't copy - source file is being updated" for unknown reason(s) to local: Rclone throwing "can't copy - source file is being updated" on Glusterfs Apr 9, 2018

ncw added a commit that referenced this issue Apr 9, 2018

local: add --local-no-check-updated to disable update checks #2206
This disables the `can't copy - source file is being updated` checks.
@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Apr 9, 2018

Owner

I added in a work-around with the --local-no-check-updated flag - can you give that a go?

https://beta.rclone.org/v1.40-061-gd5b2ec32/ (uploaded in 15-30 mins)

Owner

ncw commented Apr 9, 2018

I added in a work-around with the --local-no-check-updated flag - can you give that a go?

https://beta.rclone.org/v1.40-061-gd5b2ec32/ (uploaded in 15-30 mins)

@TorPeeto

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Apr 9, 2018

This new flag seems to circumvent the mtime issue. I will test further, but this appears to be a solid workaround. Thanks for adding this additional flag.

TorPeeto commented Apr 9, 2018

This new flag seems to circumvent the mtime issue. I will test further, but this appears to be a solid workaround. Thanks for adding this additional flag.

@ncw ncw modified the milestones: v1.41, Known Problem Apr 24, 2018

@matthewmrichter

This comment has been minimized.

Show comment
Hide comment
@matthewmrichter

matthewmrichter Aug 8, 2018

Any chance this can get merged in soon?

matthewmrichter commented Aug 8, 2018

Any chance this can get merged in soon?

@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Aug 8, 2018

Owner

The flag to work around should be in 1.42

Owner

ncw commented Aug 8, 2018

The flag to work around should be in 1.42

@TorPeeto

This comment has been minimized.

Show comment
Hide comment
@TorPeeto

TorPeeto Aug 8, 2018

Any idea on a date for that?
The beta link you pasted above now 404's....

TorPeeto commented Aug 8, 2018

Any idea on a date for that?
The beta link you pasted above now 404's....

@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Aug 10, 2018

Owner

You can find rclone 1.42 with the --local-no-check-updated flag here: https://rclone.org/downloads/

Owner

ncw commented Aug 10, 2018

You can find rclone 1.42 with the --local-no-check-updated flag here: https://rclone.org/downloads/

@ncw

This comment has been minimized.

Show comment
Hide comment
@ncw

ncw Aug 10, 2018

Owner

I'm going to close this now since I think the workaround is effective!

Owner

ncw commented Aug 10, 2018

I'm going to close this now since I think the workaround is effective!

@ncw ncw closed this Aug 10, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment