Description of problem:
Replication does not sync files that were on Master volume before the replication is created. When new files are created on Master volume it puts them into the pending state and, finally, into the skipped state. Rsync has errcode 23. The Master volume initially has 500 files in each of 500 folders.


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


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

[root@ISC235 log]# gluster volume info NASv1

Volume Name: NASv1
Type: Distribute
Volume ID: ac9b38ca-ff27-483a-9417-71c7d21ddbb0
Status: Started
Number of Bricks: 1
Transport-type: tcp
Bricks:
Brick1: 10.10.60.235:/exports/nas-segment-0001/NASv1
Options Reconfigured:
changelog.changelog: on
geo-replication.ignore-pid-check: on
geo-replication.indexing: on
server.allow-insecure: on
performance.stat-prefetch: off
nfs.disable: on
nfs.addr-namelookup: off

[root@ISC235 log]# /usr/sbin/gluster volume geo-replication NASv1 geoaccount.60.232::NAS-ASYNC status detail

MASTER NODE            MASTER VOL    MASTER BRICK                       SLAVE                      STATUS    CHECKPOINT STATUS    CRAWL STATUS       FILES SYNCD    FILES PENDING    BYTES PENDING    DELETES PENDING    FILES SKIPPED
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ISC235.naslab.local    NASv1         /exports/nas-segment-0001/NASv1    10.10.60.232::NAS-ASYNC    Active    N/A                  Changelog Crawl    0              0                0                0                  1

[root@ISC235 log]# vi /var/log/glusterfs/geo-replication/NASv1/ssh%3A%2F%2Fgeoaccount%4010.10.60.232%3Agluster%3A%2F%2F127.0.0.1%3ANAS-ASYNC.log

[2015-05-13 15:32:46.743803] I [monitor(monitor):355:distribute] <top>: slave bricks: [{'host': '10.10.60.232', 'dir': '/exports/nas-segment-0001/NAS-ASYNC'}]
[2015-05-13 15:32:46.744427] I [monitor(monitor):375:distribute] <top>: worker specs: [('/exports/nas-segment-0001/NASv1', 'ssh://geoaccount.60.232:gluster://localhost:NAS-ASYNC')]
[2015-05-13 15:32:46.745101] I [monitor(monitor):141:set_state] Monitor: new state: Initializing...
[2015-05-13 15:32:46.917603] I [monitor(monitor):215:monitor] Monitor: ------------------------------------------------------------
[2015-05-13 15:32:46.917921] I [monitor(monitor):216:monitor] Monitor: starting gsyncd worker
[2015-05-13 15:32:47.66431] I [gsyncd(/exports/nas-segment-0001/NASv1):633:main_i] <top>: syncing: gluster://localhost:NASv1 -> ssh://geoaccount.60.232:gluster://localhost:NAS-ASYNC
[2015-05-13 15:32:47.73928] I [changelogagent(agent):72:__init__] ChangelogAgent: Agent listining...
[2015-05-13 15:32:49.952930] I [master(/exports/nas-segment-0001/NASv1):75:gmaster_builder] <top>: setting up xsync change detection mode
[2015-05-13 15:32:49.953339] I [master(/exports/nas-segment-0001/NASv1):413:__init__] _GMaster: using 'rsync' as the sync engine
[2015-05-13 15:32:49.954715] I [master(/exports/nas-segment-0001/NASv1):75:gmaster_builder] <top>: setting up changelog change detection mode
[2015-05-13 15:32:49.954937] I [master(/exports/nas-segment-0001/NASv1):413:__init__] _GMaster: using 'rsync' as the sync engine
[2015-05-13 15:32:49.955810] I [master(/exports/nas-segment-0001/NASv1):75:gmaster_builder] <top>: setting up changeloghistory change detection mode
[2015-05-13 15:32:49.956043] I [master(/exports/nas-segment-0001/NASv1):413:__init__] _GMaster: using 'rsync' as the sync engine
[2015-05-13 15:32:49.998307] I [master(/exports/nas-segment-0001/NASv1):1311:register] _GMaster: xsync temp directory: /var/lib/misc/glusterfsd/NASv1/ssh%3A%2F%2Fgeoaccount%4010.10.60.232%3Agluster%3A%2F%2F127.0.0.1%3ANAS-ASYNC/7b0f5b849438ebe46c2683ce8987195e/xsync
[2015-05-13 15:32:49.998548] I [resource(/exports/nas-segment-0001/NASv1):1318:service_loop] GLUSTER: Register time: 1431556369
[2015-05-13 15:32:50.67724] I [master(/exports/nas-segment-0001/NASv1):490:crawlwrap] _GMaster: primary master with volume id ac9b38ca-ff27-483a-9417-71c7d21ddbb0 ...
[2015-05-13 15:32:50.71803] W [master(/exports/nas-segment-0001/NASv1):383:get_initial_crawl_data] _GMaster: Creating new gconf.state_detail_file.
[2015-05-13 15:32:50.72216] I [master(/exports/nas-segment-0001/NASv1):501:crawlwrap] _GMaster: crawl interval: 1 seconds
[2015-05-13 15:32:50.73456] I [master(/exports/nas-segment-0001/NASv1):1050:update_worker_status] _GMaster: Creating new /var/lib/glusterd/geo-replication/NASv1_10.10.60.232_NAS-ASYNC/_exports_nas-segment-0001_NASv1.status
[2015-05-13 15:32:50.75474] I [master(/exports/nas-segment-0001/NASv1):1226:crawl] _GMaster: starting history crawl... turns: 1, stime: (-1, 0)
[2015-05-13 15:32:50.75640] I [master(/exports/nas-segment-0001/NASv1):1229:crawl] _GMaster: stime not available, abandoning history crawl
[2015-05-13 15:32:50.77208] I [master(/exports/nas-segment-0001/NASv1):490:crawlwrap] _GMaster: primary master with volume id ac9b38ca-ff27-483a-9417-71c7d21ddbb0 ...
[2015-05-13 15:32:50.83336] I [master(/exports/nas-segment-0001/NASv1):501:crawlwrap] _GMaster: crawl interval: 60 seconds
[2015-05-13 15:32:50.86337] I [master(/exports/nas-segment-0001/NASv1):1333:crawl] _GMaster: starting hybrid crawl..., stime: (-1, 0)
[2015-05-13 15:32:51.92323] I [master(/exports/nas-segment-0001/NASv1):1343:crawl] _GMaster: processing xsync changelog /var/lib/misc/glusterfsd/NASv1/ssh%3A%2F%2Fgeoaccount%4010.10.60.232%3Agluster%3A%2F%2F127.0.0.1%3ANAS-ASYNC/7b0f5b849438ebe46c2683ce8987195e/xsync/XSYNC-CHANGELOG.1431556370
[2015-05-13 15:32:51.94180] I [master(/exports/nas-segment-0001/NASv1):1340:crawl] _GMaster: finished hybrid crawl syncing, stime: (-1, 0)
[2015-05-13 15:32:51.96489] I [master(/exports/nas-segment-0001/NASv1):490:crawlwrap] _GMaster: primary master with volume id ac9b38ca-ff27-483a-9417-71c7d21ddbb0 ...
[2015-05-13 15:32:51.100363] I [master(/exports/nas-segment-0001/NASv1):501:crawlwrap] _GMaster: crawl interval: 3 seconds
[2015-05-13 15:33:00.162770] I [master(/exports/nas-segment-0001/NASv1):1192:crawl] _GMaster: slave's time: (-1, 0)
[2015-05-13 15:33:47.196858] I [monitor(monitor):141:set_state] Monitor: new state: Stable
[2015-05-13 15:33:51.443263] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 1 turns
[2015-05-13 15:34:51.829406] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:35:52.212188] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:36:52.584650] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:37:52.927016] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:46:55.825117] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:47:56.193674] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:48:56.572449] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:49:56.938914] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:50:57.319699] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:51:57.688910] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:52:58.72496] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns
[2015-05-13 15:53:07.135729] I [master(/exports/nas-segment-0001/NASv1):1192:crawl] _GMaster: slave's time: (1431556377, 0)
[2015-05-13 15:53:17.305614] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:53:17.306004] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:53:27.437911] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:53:27.438316] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:53:37.458409] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:53:37.458834] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:53:47.598153] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:53:47.598586] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:53:57.696878] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:53:57.697302] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:54:07.911746] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:54:07.912121] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:54:17.925012] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:54:17.925395] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:54:27.996663] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:54:27.997080] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:54:38.230974] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:54:38.231404] W [master(/exports/nas-segment-0001/NASv1):1015:process] _GMaster: incomplete sync, retrying changelogs: CHANGELOG.1431557584
[2015-05-13 15:54:48.302788] W [master(/exports/nas-segment-0001/NASv1):301:regjob] _GMaster: Rsync: .gfid/b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8 [errcode: 23]
[2015-05-13 15:54:48.303196] W [master(/exports/nas-segment-0001/NASv1):996:process] _GMaster: changelogs CHANGELOG.1431557584 could not be processed - moving on...
[2015-05-13 15:54:48.304335] W [master(/exports/nas-segment-0001/NASv1):1000:process] _GMaster: SKIPPED GFID = b72f3ae3-5d08-4d1b-a24b-aff9ecec64b8
[2015-05-13 15:54:51.320489] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 4 crawls, 1 turns
[2015-05-13 15:55:51.717772] I [master(/exports/nas-segment-0001/NASv1):514:crawlwrap] _GMaster: 20 crawls, 0 turns


[root@SC232 log]# ps -ef | grep gluster
root      8430     1  0 15:31 ?        00:00:00 /usr/sbin/glusterd --pid-file=/run/glusterd.pid
1236      9573  9572  0 15:32 ?        00:00:00 /usr/bin/python /usr/libexec/glusterfs/python/syncdaemon/gsyncd.py --session-owner ac9b38ca-ff27-483a-9417-71c7d21ddbb0 -N --listen --timeout 120 gluster://localhost:NAS-ASYNC -c /var/lib/glusterd/geo-replication/gsyncd_template.conf
root      9618     1  0 15:32 ?        00:00:00 /usr/sbin/glusterfs --user-map-root=geoaccount --aux-gfid-mount --log-file=/var/log/glusterfs/geo-replication-slaves/ac9b38ca-ff27-483a-9417-71c7d21ddbb0:gluster%3A%2F%2F127.0.0.1%3ANAS-ASYNC.gluster.log --volfile-server=localhost --volfile-id=NAS-ASYNC --client-pid=-1 /var/mountbroker-root/user1236/mtpt-geoaccount-ZfHhxa
root     15651     1  0 May11 ?        00:06:29 /usr/sbin/glusterfsd -s 10.10.60.232 --volfile-id NAS-ASYNC.10.10.60.232.exports-nas-segment-0001-NAS-ASYNC -p /var/lib/glusterd/vols/NAS-ASYNC/run/10.10.60.232-exports-nas-segment-0001-NAS-ASYNC.pid -S /var/run/560e6d9030e534433560c60ed4cd9466.socket --brick-name /exports/nas-segment-0001/NAS-ASYNC -l /var/log/glusterfs/bricks/exports-nas-segment-0001-NAS-ASYNC.log --xlator-option *-posix.glusterd-uuid=c0efccec-b0a0-a091-e517-0025907a05ae --brick-port 49154 --xlator-option NAS-ASYNC-server.listen-port=49154
root     27003 10724  0 16:20 pts/1    00:00:00 grep gluster