Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1154307

Summary: Geo-Replication - Fails to handle file renaming correctly between master and slave
Product: [Community] GlusterFS Reporter: Justin Clift <jclift>
Component: geo-replicationAssignee: Aravinda VK <avishwan>
Status: CLOSED UPSTREAM QA Contact:
Severity: high Docs Contact:
Priority: high    
Version: 3.6.0CC: avishwan, bugs, chris.beck, gluster, jamoflaw, kwade
Target Milestone: ---Keywords: Triaged
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 1141379 Environment:
Last Closed: 2016-08-05 10:30:03 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1141379, 1219412    
Bug Blocks:    

Description Justin Clift 2014-10-18 14:57:01 UTC 
+++ This bug was initially created as a clone of Bug #1141379 +++

Description of problem:
Geo-Replication fails to correctly rename a file/folder when they are created and renamed quickly.

This is especially noticeable when using Windows mounted Samba shares and a new folder is created. Windows creates the folder as New Folder instantly, and gives the option of renaming. If a new name is typed, both New Folder and the newly renamed folder will be created on the remote volume.

Version-Release number of selected component (if applicable):
3.5.2

How reproducible:
Consistent

Steps to Reproduce:
1. Standard 3.5 distributed geo-rep setup 
2. Run the following as a script:

mkdir test
mv test test2
chown 100:100 test2

3. Let Geo Rep sync the directories

Actual results:
Node 1 is the master
Node 2 is the slave

[root@node1 gluster]# ls -la
total 12
drwxr-xr-x. 4 root root  4096 Sep 12 22:13 .
drwxr-xr-x. 5 root root  4096 Aug 23 17:57 ..
drwxr-xr-x. 2  100 users 4096 Sep 12 21:54 test2

[root@node2 gluster]# ls -la
total 28
drwxr-xr-x. 5 root root  8192 Aug 23 18:03 .
drwxr-xr-x. 6 root root  4096 Aug 23 17:41 ..
drwxr-xr-x. 2  100 users 8192 Aug 23 17:45 test
drwxr-xr-x. 2  100 users 8192 Aug 23 17:45 test2


Expected results:

[root@node2 gluster]# ls -la
total 28
drwxr-xr-x. 5 root root  8192 Aug 23 18:03 .
drwxr-xr-x. 6 root root  4096 Aug 23 17:41 ..
drwxr-xr-x. 2  100 users 8192 Aug 23 17:45 test2

Additional info:
None

--- Additional comment from James Payne on 2014-09-12 22:27:19 BST ---

Testing this on files gives the same results where two files will be created instead of one on the remote volume

--- Additional comment from James Payne on 2014-09-12 22:28:45 BST ---

[root@node1 gluster]# gluster volume geo-rep archive0 192.168.0.16::archive0 status detail

MASTER NODE    MASTER VOL    MASTER BRICK    SLAVE                     STATUS    CHECKPOINT STATUS    CRAWL STATUS       FILES SYNCD    FILES PENDING    BYTES PENDING    DELETES PENDING    FILES SKIPPED
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
node1          archive0      /mnt/brick0     192.168.0.16::archive0    Active    N/A                  Changelog Crawl    7              0                0                0                  0
node1          archive0      /mnt/brick1     192.168.0.16::archive0    Active    N/A                  Changelog Crawl    7              0                0                0                  0

--- Additional comment from James Payne on 2014-09-15 22:07:59 BST ---

I have installed a 3.4.5 cluster today and verified the behavior does not exist in that release if that helps.

--- Additional comment from James Payne on 2014-10-05 22:58:57 BST ---

Note that this bug is still present in 3.5.3 beta 1.

More worryingly I have also noticed the following:

Running the script below:

touch filejp1 
mv filejp1 jp1
rm -f jp1

touch filejp2
mv filejp2 jp2
rm -f jp2


Causes empty files filejp1 and filejp2 to be synced to the remote node. 

Once the above syncs with the two incorrect files run:

echo content > filejp1

More concerning is that the content which should now be in filejp1 is never synced at all, I'm guessing as filejp1 is now 'new' to the local side. The logs suggest gfid issues?

Logs as follows:
[2014-10-05 22:48:21.731467] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:21.731796] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:21.732918] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:21.733189] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:22.585704] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:22.586113] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:22.606767] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:22.607155] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:23.355896] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:23.356179] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:23.356673] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:23.356923] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:24.94445] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:24.94724] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:24.113476] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:24.113760] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:24.972117] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:24.972403] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:24.973083] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:24.973351] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:25.692605] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:25.692920] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:25.711666] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:25.711941] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:26.587243] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:26.587522] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:26.588766] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:26.589200] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:27.196441] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:27.196727] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:27.216696] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:27.216976] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:28.204376] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:28.204658] W [master(/mnt/brick0):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:28.205504] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:28.205862] W [master(/mnt/brick1):877:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1412545699
[2014-10-05 22:48:28.811841] W [master(/mnt/brick1):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:28.812125] W [master(/mnt/brick1):860:process] _GMaster: changelogs CHANGELOG.1412545699 could not be processed - moving on...
[2014-10-05 22:48:28.813575] W [master(/mnt/brick1):862:process] _GMaster: SKIPPED GFID =
[2014-10-05 22:48:29.299180] W [master(/mnt/brick0):250:regjob] <top>: Rsync: .gfid/96b35cb5-96cc-43cc-8cd3-11dace030d68 [errcode: 23]
[2014-10-05 22:48:29.299433] W [master(/mnt/brick0):860:process] _GMaster: changelogs CHANGELOG.1412545699 could not be processed - moving on...

--- Additional comment from Aravinda VK on 2014-10-15 06:52:24 BST ---

Please try the 3.6 beta 3 version. Two patches landed related to the rename and retry issues.

http://review.gluster.org/#/c/8879/
http://review.gluster.org/#/c/8880/

--- Additional comment from Kingsley Tart on 2014-10-15 11:10:18 BST ---

I have tested geo-replication on 3.6.0 beta3 on CentOS 6.5 and have managed to run into what appears to be the same issue.

I posted this to the gluster-users mailing list; my original email is below. It's worth me adding that since geo-replication broke, if I query the
volume status (in this instance, on my test1 server), I get this:

test1# gluster volume status
Another transaction is in progress. Please try again after sometime.

It's still giving this error, 24 hours later.

Original message posted to list:

I have a small script to simulate file activity for an application we
have. It breaks geo-replication within about 15 - 20 seconds when I try
it.

This is on a small Gluster test environment running in some VMs running
CentOS 6.5 and using gluster 3.6.0 beta3. I have 6 VMs - test1, test2,
test3, test4, test5 and test6. test1, test2 , test3 and test4 are
gluster servers while test5 and test6 are the clients. test3 is actually
not used in this test.


Before the test, I had a single gluster volume as follows:

test1# gluster volume status
Status of volume: gv0
Gluster process                                         Port    Online  Pid
------------------------------------------------------------------------------
Brick test1:/data/brick/gv0                             49168   Y       12017
Brick test2:/data/brick/gv0                             49168   Y       11835
NFS Server on localhost                                 2049    Y       12032
Self-heal Daemon on localhost                           N/A     Y       12039
NFS Server on test4                                     2049    Y       7934
Self-heal Daemon on test4                               N/A     Y       7939
NFS Server on test3                                     2049    Y       11768
Self-heal Daemon on test3                               N/A     Y       11775
NFS Server on test2                                     2049    Y       11849
Self-heal Daemon on test2                               N/A     Y       11855

Task Status of Volume gv0
------------------------------------------------------------------------------
There are no active volume tasks


I created a new volume and set up geo-replication as follows (as these
are test machines I only have one file system on each, hence using
"force" to create the bricks in the root FS):

test4# date ; gluster volume create gv0-slave test4:/data/brick/gv0-slave force; date
Mon Oct 13 15:03:14 BST 2014
volume create: gv0-slave: success: please start the volume to access data
Mon Oct 13 15:03:15 BST 2014

test4# date ; gluster volume start gv0-slave; date
Mon Oct 13 15:03:36 BST 2014
volume start: gv0-slave: success
Mon Oct 13 15:03:39 BST 2014

test4# date ; gluster volume geo-replication gv0 test4::gv0-slave create push-pem force ; date
Mon Oct 13 15:05:59 BST 2014
Creating geo-replication session between gv0 & test4::gv0-slave has been successful
Mon Oct 13 15:06:11 BST 2014


I then mount volume gv0 on one of the client machines. I can create
files within the gv0 volume and can see the changes being replicated to
the gv0-slave volume, so I know that geo-replication is working at the
start.

When I run my script (which quickly creates, deletes and renames files),
geo-replication breaks within a very short time. The test script output
is in
http://gluster.dogwind.com/files/georep20141013/test6_script-output.log
(I interrupted the script once I saw that geo-replication was broken).
Note that when it deletes a file, it renames any later-numbered file so
that the file numbering remains sequential with no gaps; this simulates
a real world application that we use.

If you want a copy of the test script, it's here:
http://gluster.dogwind.com/files/georep20141013/test_script.tar.gz


The various gluster log files can be downloaded from here:
http://gluster.dogwind.com/files/georep20141013/ - each log file has the
actual log file path at the top of the file.

If you want to run the test script on your own system, edit test.pl so
that @mailstores contains a directory path to a gluster volume.

My systems' timezone is BST (GMT+1 / UTC+1) so any timestamps outside of
gluster logs are in this timezone.

Let me know if you need any more info.

--- Additional comment from James Payne on 2014-10-15 22:17:57 BST ---

(In reply to Aravinda VK from comment #5)
> Please try the 3.6 beta 3 version. Two patches landed related to the rename
> and retry issues.
> 
> http://review.gluster.org/#/c/8879/
> http://review.gluster.org/#/c/8880/

Can confirm the issue still exists in beta3. 

v easy to replicate 

touch file && mv file file2

Will create 2 files on the geo-replica and only one on the primary cluster

--- Additional comment from James Payne on 2014-10-15 22:37:15 BST ---

Not sure if it helps:

Debug output for the following command:

touch file && mv file JAMESFILE

[2014-10-15 22:31:09.581840] D [repce(/mnt/brick1):209:__call__] RepceClient: call 22162:140250622097152:1413408669.58 getchanges -> ['/var/lib/misc/glusterfsd/archive0/ssh%3A%2F%2Froot%40192.168.0.16%3Agluster%3A%2F%2F127.0.0.1%3Aarchive0/63c9ed499e50ba44b851fa8a63110d6e/.processing/CHANGELOG.1413408667']
[2014-10-15 22:31:09.581922] I [master(/mnt/brick1):1182:crawl] _GMaster: slave's time: (1413408621, 0)
[2014-10-15 22:31:09.581996] D [master(/mnt/brick1):1193:crawl] _GMaster: processing changes ['/var/lib/misc/glusterfsd/archive0/ssh%3A%2F%2Froot%40192.168.0.16%3Agluster%3A%2F%2F127.0.0.1%3Aarchive0/63c9ed499e50ba44b851fa8a63110d6e/.processing/CHANGELOG.1413408667']
[2014-10-15 22:31:09.582066] D [master(/mnt/brick1):945:process] _GMaster: processing change /var/lib/misc/glusterfsd/archive0/ssh%3A%2F%2Froot%40192.168.0.16%3Agluster%3A%2F%2F127.0.0.1%3Aarchive0/63c9ed499e50ba44b851fa8a63110d6e/.processing/CHANGELOG.1413408667
[2014-10-15 22:31:09.582959] D [master(/mnt/brick1):905:process_change] _GMaster: entries: [{'uid': 0, 'gfid': 'ecdf997c-0092-452f-914e-1a1ccad3ebc0', 'gid': 0, 'mode': 33188, 'entry': '.gfid/00000000-0000-0000-0000-000000000001/file', 'op': 'CREATE'}, {'gfid': 'ecdf997c-0092-452f-914e-1a1ccad3ebc0', 'entry': '.gfid/00000000-0000-0000-0000-000000000001/file', 'stat': {'gid': 0, 'uid': 0, 'mode': 33188}, 'entry1': '.gfid/00000000-0000-0000-0000-000000000001/JAMESFILE', 'op': 'RENAME'}]
[2014-10-15 22:31:09.584343] D [repce(/mnt/brick1):191:push] RepceClient: call 22162:140250622097152:1413408669.58 entry_ops([{'uid': 0, 'gfid': 'ecdf997c-0092-452f-914e-1a1ccad3ebc0', 'gid': 0, 'mode': 33188, 'entry': '.gfid/00000000-0000-0000-0000-000000000001/file', 'op': 'CREATE'}, {'gfid': 'ecdf997c-0092-452f-914e-1a1ccad3ebc0', 'entry': '.gfid/00000000-0000-0000-0000-000000000001/file', 'stat': {'gid': 0, 'uid': 0, 'mode': 33188}, 'entry1': '.gfid/00000000-0000-0000-0000-000000000001/JAMESFILE', 'op': 'RENAME'}],) ...
[2014-10-15 22:31:09.586972] D [repce(/mnt/brick1):209:__call__] RepceClient: call 22162:140250622097152:1413408669.58 entry_ops -> None
[2014-10-15 22:31:09.587193] D [repce(/mnt/brick1):191:push] RepceClient: call 22162:140250622097152:1413408669.59 done('/var/lib/misc/glusterfsd/archive0/ssh%3A%2F%2Froot%40192.168.0.16%3Agluster%3A%2F%2F127.0.0.1%3Aarchive0/63c9ed499e50ba44b851fa8a63110d6e/.processing/CHANGELOG.1413408667',) ...

--- Additional comment from Aravinda VK on 2014-10-16 05:43:42 BST ---

(In reply to James Payne from comment #7)
> (In reply to Aravinda VK from comment #5)
> > Please try the 3.6 beta 3 version. Two patches landed related to the rename
> > and retry issues.
> > 
> > http://review.gluster.org/#/c/8879/
> > http://review.gluster.org/#/c/8880/
> 
> Can confirm the issue still exists in beta3. 
> 
> v easy to replicate 
> 
> touch file && mv file file2
> 
> Will create 2 files on the geo-replica and only one on the primary cluster

With the above patches, GFID mismatch and rsync retry issues are resolved, Do you see any data loss in Slave? both file and file2 present in slave, Is data intact in file2?

Geo-rep has a known issue with Rename handling when renamed file fall into separate brick other than the brick in which it is created.

Summarized RENAME issues here, http://supercolony.gluster.org/pipermail/gluster-devel/2014-September/042316.html

Development is in progress to fix all these RENAME issues. Will update the bug with progress.

--- Additional comment from James Payne on 2014-10-16 21:22:34 BST ---

(In reply to Aravinda VK from comment #9)
> (In reply to James Payne from comment #7)
> > (In reply to Aravinda VK from comment #5)
> > > Please try the 3.6 beta 3 version. Two patches landed related to the rename
> > > and retry issues.
> > > 
> > > http://review.gluster.org/#/c/8879/
> > > http://review.gluster.org/#/c/8880/
> > 
> > Can confirm the issue still exists in beta3. 
> > 
> > v easy to replicate 
> > 
> > touch file && mv file file2
> > 
> > Will create 2 files on the geo-replica and only one on the primary cluster
> 
> With the above patches, GFID mismatch and rsync retry issues are resolved,
> Do you see any data loss in Slave? both file and file2 present in slave, Is
> data intact in file2?
> 
> Geo-rep has a known issue with Rename handling when renamed file fall into
> separate brick other than the brick in which it is created.
> 
> Summarized RENAME issues here,
> http://supercolony.gluster.org/pipermail/gluster-devel/2014-September/042316.
> html
> 
> Development is in progress to fix all these RENAME issues. Will update the
> bug with progress.



You can get data loss on slave in the following scenario:

touch file1 && mv file2

** Wait for replication

echo contents > file1


You will find on the geo replica that file1 is now no longer consistent with the local copies. The same goes for change of attributes as well. I believe the contents of file2 in the case above will be correct but file1 will never be consistent with the local copy.
Comment 1 Justin Clift 2014-10-18 14:57:32 UTC 
This is a known problem in 3.6.0 as well. :(
Comment 3 CJ Beck 2016-03-01 15:50:22 UTC 
We are having an issue where rsync is leaving the temporary . files on remote destinations. Eventually the files do show up at the remote side, but the dot files are never cleaned up. Here's an example error message:

[2016-02-26 16:48:30.105272] W [MSGID: 113096] [posix-handle.c:754:posix_handle_hard] 0-volumename-posix: mismatching ino/dev between file /data/bricks/sdb/data/rpm-gold/repodata/.repomd.xml.OOu6Mq (298/2065) and handle /data/bricks/sdb/data/.glusterfs/7a/8b/7a8b943c-96ef-4657-ad0d-4064d3304c1d (86715/2065)
[2016-02-26 16:48:30.105290] E [MSGID: 113020] [posix.c:1221:posix_mknod] 0-volumename-posix: setting gfid on /data/bricks/sdb/data/rpm-gold/repodata/.repomd.xml.OOu6Mq failed
Comment 4 Aravinda VK 2016-08-05 10:30:03 UTC 
Rename related issues are resolved in Master, 3.7 and 3.8 releases. Gluster 3.6 will be EOL once Gluster 3.9 is released(Expected in end of september)

Closing this bug, Please reopen if the fix required for 3.6 version.