Attachment 937204 Details for Bug 1136720 – Log snippets as discussed in Comment #3

Log snippets as discussed in Comment #3

DHT_loss28th_rebal.txt (text/plain), 83.23 KB, created by Shyamsundar on 2014-09-13 12:53:25 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Shyamsundar

Created: 2014-09-13 12:53:25 UTC

Size: 83.23 KB

patch

obsolete

>=====================================================================================================
>Rebalance for f5-* from the rebalance logs
>=====================================================================================================
>Session 1: That handles the file (the sessions are time stamp sorted)
>-----------------------------------------------------------------------------------------------------
>./192.168.12.27/spacebar-rebalance.log:[2014-08-28 09:37:36.917820] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /f5-5 missing on subvol spacebar-replicate-0
>./192.168.12.27/spacebar-rebalance.log:[2014-08-28 09:37:37.325662] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/f5-5 lookup failed
>./192.168.12.27/spacebar-rebalance.log:[2014-08-28 09:38:01.346833] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-22
>./192.168.12.27/spacebar-rebalance.log:[2014-08-28 09:38:01.888827] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-10 from subvolume spacebar-replicate-6 to spacebar-replicate-22
>-----------------------------------------------------------------------------------------------------
>Expanded:
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 09:37:59.316288] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /
>[2014-08-28 09:38:00.189636] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /
>[2014-08-28 09:38:00.302385] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f93-9: attempting to move from spacebar-replicate-6 to spacebar-replicate-26
>[2014-08-28 09:38:00.305626] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:00.409087] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-26 cached_subvol spacebar-replicate-26
>===> [2014-08-28 09:38:00.409209] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f93-9 from subvolume spacebar-replicate-6 to spacebar-replicate-26
>[2014-08-28 09:38:00.409896] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:00.412654] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f98-9: attempting to move from spacebar-replicate-6 to spacebar-replicate-0
>[2014-08-28 09:38:00.413294] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.341613] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-0 cached_subvol spacebar-replicate-0
>===> [2014-08-28 09:38:01.341759] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f98-9 from subvolume spacebar-replicate-6 to spacebar-replicate-0
>[2014-08-28 09:38:01.342484] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.346833] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-22
>[2014-08-28 09:38:01.347545] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.888609] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-22 cached_subvol spacebar-replicate-22
>===> [2014-08-28 09:38:01.888827] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-10 from subvolume spacebar-replicate-6 to spacebar-replicate-22
>[2014-08-28 09:38:01.889715] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.897360] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f23-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-24
>[2014-08-28 09:38:01.898133] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.964640] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-24 cached_subvol spacebar-replicate-24
>===> [2014-08-28 09:38:01.964763] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f23-10 from subvolume spacebar-replicate-6 to spacebar-replicate-24
>[2014-08-28 09:38:01.965421] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:01.968335] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f24-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-1
>[2014-08-28 09:38:01.969026] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.035078] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-1 cached_subvol spacebar-replicate-1
>===> [2014-08-28 09:38:02.035232] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f24-10 from subvolume spacebar-replicate-6 to spacebar-replicate-1
>[2014-08-28 09:38:02.035991] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.042235] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f35-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-27
>[2014-08-28 09:38:02.042818] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.115843] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-27 cached_subvol spacebar-replicate-27
>===> [2014-08-28 09:38:02.115968] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f35-10 from subvolume spacebar-replicate-6 to spacebar-replicate-27
>[2014-08-28 09:38:02.116632] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.121073] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f61-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-17
>[2014-08-28 09:38:02.121722] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.460870] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-17 cached_subvol spacebar-replicate-17
>===> [2014-08-28 09:38:02.461011] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f61-10 from subvolume spacebar-replicate-6 to spacebar-replicate-17
>[2014-08-28 09:38:02.461677] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.467325] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f67-10: attempting to move from spacebar-replicate-6 to spacebar-replicate-13
>[2014-08-28 09:38:02.468020] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f01d9595d46]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.533148] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-13 cached_subvol spacebar-replicate-13
>===> [2014-08-28 09:38:02.533253] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f67-10 from subvolume spacebar-replicate-6 to spacebar-replicate-13
>[2014-08-28 09:38:02.533867] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x37c1443bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x38f7c5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f01d9595edf]))) 0-dict: dict is NULL
>[2014-08-28 09:38:02.714215] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir / took 2.52 secs
>[2014-08-28 09:38:02.774374] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is completed. Time taken is 3.00 secs
>
>A + C ===> [2014-08-28 09:38:02.774411] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 8, size: 8388608, lookups: 103, failures: 0, skipped: 0
>
>NOTE: Above 8 files were migrated that included f5-* and size is 8MB, so file had data here. (A: Attempted migration but not done due to space, C is completed, we will not count /hardlink/ files as they are 0 bytes in size and will not contribute to the size, remember when reading further)
>
>[2014-08-28 09:38:02.774812] W [glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15), shutting down
>====================================================================================================
>Session 2: That handles the file (the sessions are time stamp sorted)
>-----------------------------------------------------------------------------------------------------
>./192.168.12.67/spacebar-rebalance.log:[2014-08-28 10:08:39.564778] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-340: attempting to move from spacebar-replicate-22 to spacebar-replicate-17
>./192.168.12.67/spacebar-rebalance.log:[2014-08-28 10:08:40.459044] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-340 from subvolume spacebar-replicate-22 to spacebar-replicate-17
>-----------------------------------------------------------------------------------------------------
>Expanded:
>-----------------------------------------------------------------------------------------------------
>2014-08-28 10:08:37.418673] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /
>[2014-08-28 10:08:37.451475] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /
>[2014-08-28 10:08:39.083868] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f87-339: attempting to move from spacebar-replicate-22 to spacebar-replicate-20
>[2014-08-28 10:08:39.087879] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:39.557839] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-20 cached_subvol spacebar-replicate-20
>[2014-08-28 10:08:39.558257] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f87-339 from subvolume spacebar-replicate-22 to spacebar-replicate-20
>[2014-08-28 10:08:39.559226] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:39.564778] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-340: attempting to move from spacebar-replicate-22 to spacebar-replicate-17
>[2014-08-28 10:08:39.568901] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:40.458872] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-17 cached_subvol spacebar-replicate-17
>[2014-08-28 10:08:40.459044] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-340 from subvolume spacebar-replicate-22 to spacebar-replicate-17
>[2014-08-28 10:08:40.459667] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:40.464497] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f45-340: attempting to move from spacebar-replicate-22 to spacebar-replicate-16
>[2014-08-28 10:08:40.465386] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:41.407259] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-16 cached_subvol spacebar-replicate-16
>[2014-08-28 10:08:41.407527] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f45-340 from subvolume spacebar-replicate-22 to spacebar-replicate-16
>[2014-08-28 10:08:41.408652] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:41.446795] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir / took 4.00 secs
>[2014-08-28 10:08:42.187511] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /hardlinks
>[2014-08-28 10:08:42.211898] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /hardlinks
>[2014-08-28 10:08:44.017470] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /hardlinks/f3-1: attempting to move from spacebar-replicate-22 to spacebar-replicate-18
>[2014-08-28 10:08:44.019283] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.197608] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-18 cached_subvol spacebar-replicate-18
>[2014-08-28 10:08:44.197762] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /hardlinks/f3-1 from subvolume spacebar-replicate-22 to spacebar-replicate-18
>[2014-08-28 10:08:44.198889] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.203805] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /hardlinks/f33-1: attempting to move from spacebar-replicate-22 to spacebar-replicate-26
>[2014-08-28 10:08:44.204585] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.304060] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-26 cached_subvol spacebar-replicate-26
>[2014-08-28 10:08:44.304188] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /hardlinks/f33-1 from subvolume spacebar-replicate-22 to spacebar-replicate-26
>[2014-08-28 10:08:44.304867] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.312260] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /hardlinks/f38-1: attempting to move from spacebar-replicate-22 to spacebar-replicate-4
>[2014-08-28 10:08:44.312835] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.418843] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-4 cached_subvol spacebar-replicate-4
>[2014-08-28 10:08:44.419089] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /hardlinks/f38-1 from subvolume spacebar-replicate-22 to spacebar-replicate-4
>[2014-08-28 10:08:44.419775] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.425436] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /hardlinks/f45-1: attempting to move from spacebar-replicate-22 to spacebar-replicate-8
>[2014-08-28 10:08:44.426056] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f043b171d46]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.455393] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-8 cached_subvol spacebar-replicate-8
>[2014-08-28 10:08:44.455811] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /hardlinks/f45-1 from subvolume spacebar-replicate-22 to spacebar-replicate-8
>[2014-08-28 10:08:44.456507] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3219a43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3cd1e5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f043b171edf]))) 0-dict: dict is NULL
>[2014-08-28 10:08:44.510245] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir /hardlinks took 2.30 secs
>[2014-08-28 10:08:44.687362] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is completed. Time taken is 7.00 secs
>
>A + C ===> [2014-08-28 10:08:44.687401] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 7, size: 3145728, lookups: 258, failures: 0, skipped: 0
>NOTE: File is healthy here as well, 7 files migrated, of which only 3 are not from the hardlink directory and the size is 3MB, so all is well till now
>
>[2014-08-28 10:08:44.687770] W [glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15), shutting down
>=====================================================================================================
>Session 3: That handles the file (the sessions are time stamp sorted)
>-----------------------------------------------------------------------------------------------------
>XXX> HOW DID THE FILE'S CACHED LOCATION MOVE FROM R17 to R2??? (See NFS logs below)
>./192.168.12.17/spacebar-rebalance.log:[2014-08-28 10:24:25.015226] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-15
>./192.168.12.17/spacebar-rebalance.log:[2014-08-28 10:24:25.262409] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-3 from subvolume spacebar-replicate-2 to spacebar-replicate-15
>-----------------------------------------------------------------------------------------------------
>Expanded:
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:24:24.876101] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /
>[2014-08-28 10:24:24.941999] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /
>[2014-08-28 10:24:24.980649] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f2-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-9
>[2014-08-28 10:24:24.982197] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:24.993424] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-2) with higher disk space to a node (spacebar-replicate-9) with lesser disk space (/f2-3)
>[2014-08-28 10:24:24.995883] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:24.999827] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f3-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-25
>[2014-08-28 10:24:25.000635] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.012166] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-2) with higher disk space to a node (spacebar-replicate-25) with lesser disk space (/f3-3)
>[2014-08-28 10:24:25.012482] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.015226] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-15
>[2014-08-28 10:24:25.015599] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.262267] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-15 cached_subvol spacebar-replicate-15
>[2014-08-28 10:24:25.262409] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-3 from subvolume spacebar-replicate-2 to spacebar-replicate-15
>[2014-08-28 10:24:25.263227] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.266786] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f27-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-4
>[2014-08-28 10:24:25.267681] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.284680] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-2) with higher disk space to a node (spacebar-replicate-4) with lesser disk space (/f27-3)
>[2014-08-28 10:24:25.285579] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.289335] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f39-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-11
>[2014-08-28 10:24:25.290080] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.360558] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-11 cached_subvol spacebar-replicate-11
>[2014-08-28 10:24:25.360692] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f39-3 from subvolume spacebar-replicate-2 to spacebar-replicate-11
>[2014-08-28 10:24:25.372595] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.378433] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f68-3: attempting to move from spacebar-replicate-2 to spacebar-replicate-5
>[2014-08-28 10:24:25.379898] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7f552bb40d46]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.399211] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-2) with higher disk space to a node (spacebar-replicate-5) with lesser disk space (/f68-3)
>[2014-08-28 10:24:25.399858] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3709c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7f5539d9ca62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7f552bb40edf]))) 0-dict: dict is NULL
>[2014-08-28 10:24:25.888938] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir / took 0.95 secs
>[2014-08-28 10:24:25.917801] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /hardlinks
>[2014-08-28 10:24:26.217208] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /hardlinks
>[2014-08-28 10:24:27.506083] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link13-136 missing on subvol spacebar-replicate-14
>[2014-08-28 10:24:27.515479] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-14 cached_subvol null
>[2014-08-28 10:24:27.515689] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link13-136 lookup failed
>[2014-08-28 10:24:27.622541] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link19-136 missing on subvol spacebar-replicate-4
>[2014-08-28 10:24:27.627535] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-4 cached_subvol null
>[2014-08-28 10:24:27.627718] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link19-136 lookup failed
>[2014-08-28 10:24:27.676691] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link29-136 missing on subvol spacebar-replicate-18
>[2014-08-28 10:24:27.680832] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-18 cached_subvol null
>[2014-08-28 10:24:27.680991] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link29-136 lookup failed
>[2014-08-28 10:24:27.714753] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link31-136 missing on subvol spacebar-replicate-19
>[2014-08-28 10:24:27.732487] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-19 cached_subvol null
>[2014-08-28 10:24:27.732851] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link31-136 lookup failed
>[2014-08-28 10:24:27.733622] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link36-136 missing on subvol spacebar-replicate-26
>[2014-08-28 10:24:27.785514] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-26 cached_subvol null
>[2014-08-28 10:24:27.785658] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link36-136 lookup failed
>[2014-08-28 10:24:27.972948] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir /hardlinks took 1.76 secs
>[2014-08-28 10:24:28.220974] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is completed. Time taken is 4.00 secs
>
>A + C XXX> [2014-08-28 10:24:28.221059] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 6, size: 5242880, lookups: 257, failures: 0, skipped: 0
>NOTE: Here the size is incorrect, it has 1MB less, pointing to the problem on the file having happened between f5-340 and f5-3 (i.e Session 2 - 3)
>
>[2014-08-28 10:24:28.221522] W [glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15), shutting down
>=====================================================================================================
>Session 4: That handles the file (the sessions are time stamp sorted)
>-----------------------------------------------------------------------------------------------------
>./192.168.12.49/spacebar-rebalance.log:[2014-08-28 10:26:06.029522] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-12: attempting to move from spacebar-replicate-15 to spacebar-replicate-16
>./192.168.12.49/spacebar-rebalance.log:[2014-08-28 10:26:06.183263] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-12 from subvolume spacebar-replicate-15 to spacebar-replicate-16
>-----------------------------------------------------------------------------------------------------
>Expanded:
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:26:05.705453] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /
>[2014-08-28 10:26:05.835644] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /
>[2014-08-28 10:26:06.016310] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f94-11: attempting to move from spacebar-replicate-15 to spacebar-replicate-18
>[2014-08-28 10:26:06.016952] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fd79e4ffd46]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.026468] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-15) with higher disk space to a node (spacebar-replicate-18) with lesser disk space (/f94-11)
>[2014-08-28 10:26:06.027206] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fd79e4ffedf]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.029522] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f5-12: attempting to move from spacebar-replicate-15 to spacebar-replicate-16
>[2014-08-28 10:26:06.030253] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fd79e4ffd46]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.183072] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-16 cached_subvol spacebar-replicate-16
>[2014-08-28 10:26:06.183263] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /f5-12 from subvolume spacebar-replicate-15 to spacebar-replicate-16
>[2014-08-28 10:26:06.183967] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fd79e4ffedf]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.190293] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f14-12: attempting to move from spacebar-replicate-15 to spacebar-replicate-0
>[2014-08-28 10:26:06.191046] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fd79e4ffd46]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.232641] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-15) with higher disk space to a node (spacebar-replicate-0) with lesser disk space (/f14-12)
>[2014-08-28 10:26:06.233770] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fd79e4ffedf]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.239985] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /f46-12: attempting to move from spacebar-replicate-15 to spacebar-replicate-2
>[2014-08-28 10:26:06.240620] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fd79e4ffd46]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.252208] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-15) with higher disk space to a node (spacebar-replicate-2) with lesser disk space (/f46-12)
>[2014-08-28 10:26:06.252917] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x3e69e43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x3a6fe5ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fd79e4ffedf]))) 0-dict: dict is NULL
>[2014-08-28 10:26:06.556628] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir / took 0.72 secs
>[2014-08-28 10:26:06.585623] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /hardlinks
>[2014-08-28 10:26:06.710866] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /hardlinks
>[2014-08-28 10:26:07.601630] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link11-153 missing on subvol spacebar-replicate-19
>[2014-08-28 10:26:07.619862] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-19 cached_subvol null
>[2014-08-28 10:26:07.620034] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link11-153 lookup failed
>[2014-08-28 10:26:07.710509] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link19-153 missing on subvol spacebar-replicate-24
>[2014-08-28 10:26:07.716180] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-24 cached_subvol null
>[2014-08-28 10:26:07.716270] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link19-153 lookup failed
>[2014-08-28 10:26:07.894818] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link10-153 missing on subvol spacebar-replicate-11
>[2014-08-28 10:26:07.903697] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-11 cached_subvol null
>[2014-08-28 10:26:07.903881] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link10-153 lookup failed
>[2014-08-28 10:26:08.179940] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /hardlinks/link13-153 missing on subvol spacebar-replicate-1
>[2014-08-28 10:26:08.184487] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-1 cached_subvol null
>[2014-08-28 10:26:08.184613] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/hardlinks/link13-153 lookup failed
>[2014-08-28 10:26:08.364627] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir /hardlinks took 1.65 secs
>[2014-08-28 10:26:08.560437] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is completed. Time taken is 3.00 secs
>
>A + C XXX> [2014-08-28 10:26:08.560523] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 4, size: 3145728, lookups: 254, failures: 0, skipped: 0
>NOTE: Problem persists, just a note.
>
>[2014-08-28 10:26:08.561027] W [glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15), shutting down
>=====================================================================================================
>Session 5: That handles the file (the sessions are time stamp sorted)
>-----------------------------------------------------------------------------------------------------
>./192.168.12.53/spacebar-rebalance.log:[2014-08-28 10:32:21.829916] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /test/f5-19: attempting to move from spacebar-replicate-16 to spacebar-replicate-0
>./192.168.12.53/spacebar-rebalance.log:[2014-08-28 10:32:21.881456] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /test/f5-19 from subvolume spacebar-replicate-16 to spacebar-replicate-0
>-----------------------------------------------------------------------------------------------------
>Expanded:
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:32:21.259082] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /
>[2014-08-28 10:32:21.338087] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /
>[2014-08-28 10:32:21.360657] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir / took 0.02 secs
>[2014-08-28 10:32:21.379420] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /test
>[2014-08-28 10:32:21.401296] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /test
>[2014-08-28 10:32:21.743931] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /test/f41-17: attempting to move from spacebar-replicate-16 to spacebar-replicate-26
>[2014-08-28 10:32:21.744929] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fc154eb7d46]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.766490] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-16) with higher disk space to a node (spacebar-replicate-26) with lesser disk space (/test/f41-17)
>[2014-08-28 10:32:21.767172] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fc154eb7edf]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.778252] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /test/f45-17: attempting to move from spacebar-replicate-16 to spacebar-replicate-3
>[2014-08-28 10:32:21.779047] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fc154eb7d46]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.792346] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-16) with higher disk space to a node (spacebar-replicate-3) with lesser disk space (/test/f45-17)
>[2014-08-28 10:32:21.797525] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fc154eb7edf]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.801524] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /test/f53-17: attempting to move from spacebar-replicate-16 to spacebar-replicate-11
>[2014-08-28 10:32:21.802307] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fc154eb7d46]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.813369] W [MSGID: 109023] [dht-rebalance.c:534:__dht_check_free_space] 0-spacebar-dht: data movement attempted from node (spacebar-replicate-16) with higher disk space to a node (spacebar-replicate-11) with lesser disk space (/test/f53-17)
>[2014-08-28 10:32:21.814434] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fc154eb7edf]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.829916] I [dht-rebalance.c:865:dht_migrate_file] 0-spacebar-dht: /test/f5-19: attempting to move from spacebar-replicate-16 to spacebar-replicate-0
>[2014-08-28 10:32:21.830925] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x2a6) [0x7fc154eb7d46]))) 0-dict: dict is NULL
>[2014-08-28 10:32:21.881280] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-0 cached_subvol spacebar-replicate-0
>[2014-08-28 10:32:21.881456] I [MSGID: 109022] [dht-rebalance.c:1143:dht_migrate_file] 0-spacebar-dht: completed migration of /test/f5-19 from subvolume spacebar-replicate-16 to spacebar-replicate-0
>[2014-08-28 10:32:21.883400] W [dict.c:480:dict_unref] (-->/lib64/libc.so.6() [0x36f6c43bf0] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x37f225ba62] (-->/usr/lib64/glusterfs/3.6.0.27/xlator/cluster/distribute.so(dht_migrate_file+0x43f) [0x7fc154eb7edf]))) 0-dict: dict is NULL
>[2014-08-28 10:32:22.043766] I [dht-rebalance.c:1633:gf_defrag_migrate_data] 0-spacebar-dht: Migration operation on dir /test took 0.64 secs
>[2014-08-28 10:32:22.084747] I [dht-common.c:3242:dht_setxattr] 0-spacebar-dht: fixing the layout of /test/hardlinks
>[2014-08-28 10:32:22.223805] I [dht-rebalance.c:1393:gf_defrag_migrate_data] 0-spacebar-dht: migrate data called on /test/hardlinks
>[2014-08-28 10:32:22.696999] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /test/hardlinks/link89-218 missing on subvol spacebar-replicate-23
>[2014-08-28 10:32:22.702438] I [MSGID: 109029] [dht-rebalance.c:2120:gf_defrag_stop] 0-: Received stop command on rebalance
>[2014-08-28 10:32:22.702532] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is stopped. Time taken is 1.00 secs
>[2014-08-28 10:32:22.702564] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 4, size: 3145728, lookups: 132, failures: 0, skipped: 0
>[2014-08-28 10:32:22.706749] I [dht-common.c:1084:dht_lookup_everywhere_done] 0-spacebar-dht: STATUS: hashed_subvol spacebar-replicate-23 cached_subvol null
>[2014-08-28 10:32:22.706870] E [MSGID: 109023] [dht-rebalance.c:1495:gf_defrag_migrate_data] 0-spacebar-dht: Migrate file failed:/test/hardlinks/link89-218 lookup failed
>[2014-08-28 10:32:22.708862] E [MSGID: 109016] [dht-rebalance.c:1799:gf_defrag_fix_layout] 0-spacebar-dht: Fix layout failed for /test/hardlinks
>[2014-08-28 10:32:22.710811] E [MSGID: 109016] [dht-rebalance.c:1799:gf_defrag_fix_layout] 0-spacebar-dht: Fix layout failed for /test
>[2014-08-28 10:32:22.712990] I [MSGID: 109028] [dht-rebalance.c:2095:gf_defrag_status_get] 0-glusterfs: Rebalance is stopped. Time taken is 1.00 secs
>
>A + C XXX> [2014-08-28 10:32:22.713060] I [MSGID: 109028] [dht-rebalance.c:2099:gf_defrag_status_get] 0-glusterfs: Files migrated: 4, size: 3145728, lookups: 132, failures: 2, skipped: 0
>NOTE: Problem persists (i.e size mismatch in terms of number of files reported as migrated versus, size
>
>[2014-08-28 10:32:22.713641] W [glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15), shutting down
>=====================================================================================================
>NFS Logs
>=====================================================================================================
>Renaming f5-340 -> f5-1 (no issues and time stamps and cached/hashed all represent good data)
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:18:15.242106] D [nfs3-helpers.c:1653:nfs3_log_fh_entry_call] 0-nfs-nfsv3: XID: c0e38236, LOOKUP: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-340
>[2014-08-28 10:18:15.242186] D [MSGID: 0] [dht-common.c:2191:dht_lookup] 0-spacebar-dht: Calling fresh lookup for /f5-340 on spacebar-replicate-17
>[2014-08-28 10:18:15.248441] D [afr-common.c:1572:afr_lookup_select_read_child] 0-spacebar-replicate-17: Source selected as 1 for /f5-340
>[2014-08-28 10:18:15.248482] D [MSGID: 0] [dht-common.c:1819:dht_lookup_cbk] 0-spacebar-dht: fresh_lookup returned for /f5-340 with op_ret 0 and op_errno 0
>[2014-08-28 10:18:15.249324] D [nfs3-helpers.c:1670:nfs3_log_rename_call] 0-nfs-nfsv3: XID: c2e38236, RENAME: args: Src: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-340, Dst: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-1
>[2014-08-28 10:18:15.259705] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-340 (hash=spacebar-replicate-17/cache=spacebar-replicate-17) => /f5-1 (hash=spacebar-replicate-21/cache=<nul>)
>[2014-08-28 10:18:15.261471] D [afr-common.c:138:afr_lookup_xattr_req_prepare] 0-spacebar-replicate-17: /f5-340: failed to get the gfid from dict
>[2014-08-28 10:18:15.262541] D [afr-common.c:1572:afr_lookup_select_read_child] 0-spacebar-replicate-17: Source selected as 1 for /f5-340
>[2014-08-28 10:18:15.287232] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-340 @ spacebar-replicate-17
>-----------------------------------------------------------------------------------------------------
>Failed rename of f5-2 -> f5-3 (failure unknown mostly a lookup failure, not an issue)
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:24:16.995839] D [nfs3-helpers.c:1670:nfs3_log_rename_call] 0-nfs-nfsv3: XID: 40c58336, RENAME: args: Src: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-2, Dst: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-3
>[2014-08-28 10:24:16.995977] D [MSGID: 0] [dht-common.c:2191:dht_lookup] 0-spacebar-dht: Calling fresh lookup for /f5-3 on spacebar-replicate-15
>[2014-08-28 10:24:16.996667] D [MSGID: 0] [dht-common.c:1819:dht_lookup_cbk] 0-spacebar-dht: fresh_lookup returned for /f5-3 with op_ret -1 and op_errno 2
>[2014-08-28 10:24:16.996702] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /f5-3 missing on subvol spacebar-replicate-15
>[2014-08-28 10:24:17.000092] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-15
>[2014-08-28 10:24:17.004343] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-0
>[2014-08-28 10:24:17.004476] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-1
>[2014-08-28 10:24:17.004549] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-2
>[2014-08-28 10:24:17.004678] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-3
>[2014-08-28 10:24:17.004749] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-4
>[2014-08-28 10:24:17.004876] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-5
>[2014-08-28 10:24:17.005045] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-8
>[2014-08-28 10:24:17.005119] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-6
>[2014-08-28 10:24:17.005214] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-7
>[2014-08-28 10:24:17.005317] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-9
>[2014-08-28 10:24:17.005404] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-10
>[2014-08-28 10:24:17.005494] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-12
>[2014-08-28 10:24:17.005649] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-13
>[2014-08-28 10:24:17.005718] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-14
>[2014-08-28 10:24:17.005808] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-16
>[2014-08-28 10:24:17.005920] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-17
>[2014-08-28 10:24:17.006068] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-18
>[2014-08-28 10:24:17.006140] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-19
>[2014-08-28 10:24:17.006274] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-20
>[2014-08-28 10:24:17.006359] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-21
>[2014-08-28 10:24:17.006446] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-22
>[2014-08-28 10:24:17.006545] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-23
>[2014-08-28 10:24:17.006785] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-11
>[2014-08-28 10:24:17.008980] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-24
>[2014-08-28 10:24:17.009050] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-25
>[2014-08-28 10:24:17.009149] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-26
>[2014-08-28 10:24:17.009218] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-3) from subvol spacebar-replicate-27
>[2014-08-28 10:24:17.009286] D [MSGID: 0] [dht-common.c:1145:dht_lookup_everywhere_done] 0-spacebar-dht: There was no cached file and  unlink on hashed is not skipped /f5-3
>[2014-08-28 10:24:17.009354] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-2 (hash=spacebar-replicate-4/cache=spacebar-replicate-2) => /f5-3 (hash=spacebar-replicate-15/cache=<nul>)
>-----------------------------------------------------------------------------------------------------
>Rename of f5-3 -> f5-4 (Succesful and does not collide with rebalance)
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 10:24:28.572775] D [nfs3-helpers.c:1670:nfs3_log_rename_call] 0-nfs-nfsv3: XID: a0cf8336, RENAME: args: Src: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-3, Dst: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-4
>[2014-08-28 10:24:28.583093] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-3 (hash=spacebar-replicate-15/cache=spacebar-replicate-15) => /f5-4 (hash=spacebar-replicate-26/cache=<nul>)
>[2014-08-28 10:24:28.583793] D [afr-common.c:138:afr_lookup_xattr_req_prepare] 0-spacebar-replicate-15: /f5-3: failed to get the gfid from dict
>[2014-08-28 10:24:28.587202] D [afr-common.c:1572:afr_lookup_select_read_child] 0-spacebar-replicate-15: Source selected as 0 for /f5-3
>[2014-08-28 10:24:28.597993] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-3 @ spacebar-replicate-15
>[2014-08-28 10:27:37.840282] D [nfs3-helpers.c:1653:nfs3_log_fh_entry_call] 0-nfs-nfsv3: XID: 2c7a8436, LOOKUP: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-30
>-----------------------------------------------------------------------------------------------------
>Tracing cached volume for f5-1 OR 2 OR 3 to find evidence of cache change above (i.e R17 to R2)
>-----------------------------------------------------------------------------------------------------
>[root@gqas003 192.168.12.13-nfs-from-12]# cat ./nfs_f5.log  | grep rename | grep dht
>[2014-08-28 09:45:29.570147] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /hardlinks/f5 (hash=spacebar-replicate-27/cache=spacebar-replicate-27) => /hardlinks/f5-1 (hash=spacebar-replicate-4/cache=<nul>)
>[2014-08-28 10:18:15.259705] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-340 (hash=spacebar-replicate-17/cache=spacebar-replicate-17) => /f5-1 (hash=spacebar-replicate-21/cache=<nul>)
>[2014-08-28 10:18:15.287232] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-340 @ spacebar-replicate-17
>
>OUT OF ORDER RENAME??? f5-57 -> f5-1??? and here is where the cached changes to R2 (see full logs below for f5-57)
>[2014-08-28 10:19:18.896736] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-57 (hash=spacebar-replicate-2/cache=spacebar-replicate-2) => /f5-1 (hash=spacebar-replicate-21/cache=spacebar-replicate-17)
>
>[2014-08-28 10:19:18.917262] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-57 @ spacebar-replicate-2
>[2014-08-28 10:19:18.917377] D [MSGID: 0] [dht-rename.c:772:dht_rename_cbk] 0-spacebar-dht: deleting old dst datafile /f5-1 @ spacebar-replicate-17
>[2014-08-28 10:24:05.684857] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-1 (hash=spacebar-replicate-21/cache=spacebar-replicate-2) => /f5-2 (hash=spacebar-replicate-4/cache=<nul>)
>[2014-08-28 10:24:05.701378] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-1 @ spacebar-replicate-2
>[2014-08-28 10:24:05.701488] D [MSGID: 0] [dht-rename.c:755:dht_rename_cbk] 0-spacebar-dht: deleting old src linkfile /f5-1 @ spacebar-replicate-21
>[2014-08-28 10:24:17.009354] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-2 (hash=spacebar-replicate-4/cache=spacebar-replicate-2) => /f5-3 (hash=spacebar-replicate-15/cache=<nul>)
>[2014-08-28 10:24:17.033964] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-2 @ spacebar-replicate-2
>[2014-08-28 10:24:17.034112] D [MSGID: 0] [dht-rename.c:755:dht_rename_cbk] 0-spacebar-dht: deleting old src linkfile /f5-2 @ spacebar-replicate-4
>[2014-08-28 10:24:28.583093] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-3 (hash=spacebar-replicate-15/cache=spacebar-replicate-15) => /f5-4 (hash=spacebar-replicate-26/cache=<nul>)
>[2014-08-28 10:24:28.597993] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-3 @ spacebar-replicate-15
>[2014-08-28 10:24:39.990689] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-4 (hash=spacebar-replicate-26/cache=spacebar-replicate-15) => /f5-5 (hash=spacebar-replicate-0/cache=<nul>)
>[2014-08-28 10:24:39.999019] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-4 @ spacebar-replicate-15
>[2014-08-28 10:24:39.999139] D [MSGID: 0] [dht-rename.c:755:dht_rename_cbk] 0-spacebar-dht: deleting old src linkfile /f5-4 @ spacebar-replicate-26
>[2014-08-28 10:24:50.841217] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-5 (hash=spacebar-replicate-0/cache=spacebar-replicate-15) => /f5-6 (hash=spacebar-replicate-2/cache=<nul>)
>[2014-08-28 10:24:50.856096] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-5 @ spacebar-replicate-15
>[2014-08-28 10:24:50.856236] D [MSGID: 0] [dht-rename.c:755:dht_rename_cbk] 0-spacebar-dht: deleting old src linkfile /f5-5 @ spacebar-replicate-0
>-----------------------------------------------------------------------------------------------------
>Tracing life of f5-57 (See comments below)
>-----------------------------------------------------------------------------------------------------
>[root@gqas003 192.168.12.13-nfs-from-12]# cat ./nfs_f5.log  | grep f5-57
>[2014-08-28 09:42:59.752085] D [nfs3-helpers.c:1653:nfs3_log_fh_entry_call] 0-nfs-nfsv3: XID: 543b8236, LOOKUP: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-57
>[2014-08-28 09:42:59.752208] D [MSGID: 0] [dht-common.c:2191:dht_lookup] 0-spacebar-dht: Calling fresh lookup for /f5-57 on spacebar-replicate-2
>[2014-08-28 09:42:59.752884] D [MSGID: 0] [dht-common.c:1819:dht_lookup_cbk] 0-spacebar-dht: fresh_lookup returned for /f5-57 with op_ret -1 and op_errno 2
>[2014-08-28 09:42:59.752914] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /f5-57 missing on subvol spacebar-replicate-2
>[2014-08-28 09:42:59.755587] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-0
>[2014-08-28 09:42:59.755684] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-1
>[2014-08-28 09:42:59.755732] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-2
>[2014-08-28 09:42:59.755781] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-3
>[2014-08-28 09:42:59.755912] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-4
>[2014-08-28 09:42:59.756000] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-5
>[2014-08-28 09:42:59.756094] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-6
>[2014-08-28 09:42:59.756137] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-7
>[2014-08-28 09:42:59.756221] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-8
>[2014-08-28 09:42:59.756275] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-10
>[2014-08-28 09:42:59.756346] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-9
>[2014-08-28 09:42:59.756407] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-12
>[2014-08-28 09:42:59.756447] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-11
>[2014-08-28 09:42:59.756495] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-13
>[2014-08-28 09:42:59.756532] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-14
>[2014-08-28 09:42:59.756619] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-16
>[2014-08-28 09:42:59.756685] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-15
>[2014-08-28 09:42:59.756726] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-18
>[2014-08-28 09:42:59.756765] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-17
>[2014-08-28 09:42:59.756837] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-20
>[2014-08-28 09:42:59.756956] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-19
>[2014-08-28 09:42:59.757004] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-21
>[2014-08-28 09:42:59.757072] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-23
>[2014-08-28 09:42:59.757112] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-22
>[2014-08-28 09:42:59.757194] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-26
>[2014-08-28 09:42:59.757237] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-25
>[2014-08-28 09:42:59.757289] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-24
>[2014-08-28 09:42:59.757329] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-27
>[2014-08-28 09:42:59.757362] D [MSGID: 0] [dht-common.c:1145:dht_lookup_everywhere_done] 0-spacebar-dht: There was no cached file and  unlink on hashed is not skipped /f5-57
>[2014-08-28 09:42:59.757739] D [nfs3-helpers.c:1653:nfs3_log_fh_entry_call] 0-nfs-nfsv3: XID: 553b8236, LOOKUP: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-57
>[2014-08-28 09:42:59.757943] D [MSGID: 0] [dht-common.c:2191:dht_lookup] 0-spacebar-dht: Calling fresh lookup for /f5-57 on spacebar-replicate-2
>[2014-08-28 09:42:59.758602] D [MSGID: 0] [dht-common.c:1819:dht_lookup_cbk] 0-spacebar-dht: fresh_lookup returned for /f5-57 with op_ret -1 and op_errno 2
>[2014-08-28 09:42:59.758631] I [dht-common.c:1823:dht_lookup_cbk] 0-spacebar-dht: Entry /f5-57 missing on subvol spacebar-replicate-2
>[2014-08-28 09:42:59.761809] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-0
>[2014-08-28 09:42:59.761887] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-2
>[2014-08-28 09:42:59.761943] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-1
>[2014-08-28 09:42:59.761996] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-3
>[2014-08-28 09:42:59.762070] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-4
>[2014-08-28 09:42:59.762190] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-5
>[2014-08-28 09:42:59.762243] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-6
>[2014-08-28 09:42:59.762319] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-7
>[2014-08-28 09:42:59.762373] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-8
>[2014-08-28 09:42:59.762422] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-9
>[2014-08-28 09:42:59.762479] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-10
>[2014-08-28 09:42:59.762516] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-11
>[2014-08-28 09:42:59.762562] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-12
>[2014-08-28 09:42:59.762641] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-14
>[2014-08-28 09:42:59.762681] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-13
>[2014-08-28 09:42:59.762754] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-15
>[2014-08-28 09:42:59.762809] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-16
>[2014-08-28 09:42:59.762866] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-17
>[2014-08-28 09:42:59.762914] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-18
>[2014-08-28 09:42:59.762951] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-19
>[2014-08-28 09:42:59.763007] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-20
>[2014-08-28 09:42:59.763045] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-21
>[2014-08-28 09:42:59.763127] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-22
>[2014-08-28 09:42:59.763205] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-23
>[2014-08-28 09:42:59.763248] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-24
>[2014-08-28 09:42:59.763304] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-25
>[2014-08-28 09:42:59.763352] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-26
>[2014-08-28 09:42:59.763389] D [MSGID: 0] [dht-common.c:1411:dht_lookup_everywhere_cbk] 0-spacebar-dht: returned with op_ret -1 and op_errno 2 (/f5-57) from subvol spacebar-replicate-27
>[2014-08-28 09:42:59.763423] D [MSGID: 0] [dht-common.c:1145:dht_lookup_everywhere_done] 0-spacebar-dht: There was no cached file and  unlink on hashed is not skipped /f5-57
>
>COMMENT: Ok did not find f5-57 and created it??? So now we have a 0 byte f5-57 file that gets renamed to f5-1 below.
>
>[2014-08-28 09:42:59.763806] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: 563b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-57, mode: UNCHECKED
>
>[2014-08-28 10:19:18.896667] D [nfs3-helpers.c:1670:nfs3_log_rename_call] 0-nfs-nfsv3: XID: 170f8336, RENAME: args: Src: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-57, Dst: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-1
>
>NOTE: Renamed below...
>[2014-08-28 10:19:18.896736] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f5-57 (hash=spacebar-replicate-2/cache=spacebar-replicate-2) => /f5-1 (hash=spacebar-replicate-21/cache=spacebar-replicate-17)
>
>[2014-08-28 10:19:18.897685] D [afr-common.c:138:afr_lookup_xattr_req_prepare] 0-spacebar-replicate-2: /f5-57: failed to get the gfid from dict
>[2014-08-28 10:19:18.901509] D [afr-common.c:1572:afr_lookup_select_read_child] 0-spacebar-replicate-2: Source selected as 0 for /f5-57
>[2014-08-28 10:19:18.917262] D [MSGID: 0] [dht-rename.c:733:dht_rename_cbk] 0-spacebar-dht: deleting old src datafile /f5-57 @ spacebar-replicate-2
>===============================================================
>So what happened to the file f5-1 that f5-340 was renamed to and exist in R17? It is unlinked as it is an existing file as above, and the log message for it is at level TRACE.
>
>For the other files that have duplicate files, i.e f4-19 and f4-57 the GFID of these files are different, so it means they also went through the same loop but somehow managed to live. Checking the logs for the same.
>
>-----------------------------------------------------------------------------------------------------
>From the CREATE logs of nfs it looks like, the 57 numbered files are present for the files that have shown the problem, 
>-----------------------------------------------------------------------------------------------------
>[2014-08-28 09:42:59.688776] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: 313b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f4-57, mode: UNCHECKED
>[2014-08-28 09:42:59.692742] D [nfs3-helpers.c:3470:nfs3_log_newfh_res] 0-nfs-nfsv3: XID: 313b8236, CREATE: NFS: 0(Call completed successfully.), POSIX: 0(Success), FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 3f830f32-4075-44d3-83d6-043accbef83f
>[2014-08-28 09:42:59.763806] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: 563b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f5-57, mode: UNCHECKED
>[2014-08-28 09:42:59.765298] D [nfs3-helpers.c:3470:nfs3_log_newfh_res] 0-nfs-nfsv3: XID: 563b8236, CREATE: NFS: 0(Call completed successfully.), POSIX: 0(Success), FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid b235dad2-4b3a-4d11-9259-28070e5da7f9
>[2014-08-28 09:42:59.829130] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: 793b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f6-57, mode: UNCHECKED
>[2014-08-28 09:42:59.830673] D [nfs3-helpers.c:3470:nfs3_log_newfh_res] 0-nfs-nfsv3: XID: 793b8236, CREATE: NFS: 0(Call completed successfully.), POSIX: 0(Success), FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 6ff56778-c0a4-4865-9bfa-a0ea611117a0
>[2014-08-28 09:42:59.941227] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: bd3b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f8-57, mode: UNCHECKED
>[2014-08-28 09:42:59.942656] D [nfs3-helpers.c:3470:nfs3_log_newfh_res] 0-nfs-nfsv3: XID: bd3b8236, CREATE: NFS: 0(Call completed successfully.), POSIX: 0(Success), FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 49772fbc-da72-4030-a666-a64f5795831f
>[2014-08-28 09:43:00.012007] D [nfs3-helpers.c:1696:nfs3_log_create_call] 0-nfs-nfsv3: XID: e03b8236, CREATE: args: FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid 00000000-0000-0000-0000-000000000001, name: f9-57, mode: UNCHECKED
>[2014-08-28 09:43:00.016018] D [nfs3-helpers.c:3470:nfs3_log_newfh_res] 0-nfs-nfsv3: XID: e03b8236, CREATE: NFS: 0(Call completed successfully.), POSIX: 0(Success), FH: exportid 740a675d-64fb-4e17-8869-d8a1aeecdad8, gfid e5a67d28-032f-4d7f-a574-13fcc08761a5
>
>-----------------------------------------------------------------------------------------------------
>Let's check why f4-19 did not get deleted...
>-----------------------------------------------------------------------------------------------------
>[root@gqas003 192.168.12.13-nfs-from-12]# cat ./nfs_28th.log | grep f4- | grep renaming
>[2014-08-28 09:45:29.543460] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /hardlinks/f4 (hash=spacebar-replicate-13/cache=spacebar-replicate-13) => /hardlinks/f4-1 (hash=spacebar-replicate-25/cache=<nul>)
>[2014-08-28 10:18:15.204011] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-340 (hash=spacebar-replicate-7/cache=spacebar-replicate-7) => /f4-1 (hash=spacebar-replicate-18/cache=<nul>)
>[2014-08-28 10:24:05.587444] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-1 (hash=spacebar-replicate-18/cache=spacebar-replicate-7) => /f4-2 (hash=spacebar-replicate-10/cache=<nul>)
>[2014-08-28 10:24:16.903100] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-2 (hash=spacebar-replicate-10/cache=spacebar-replicate-7) => /f4-3 (hash=spacebar-replicate-16/cache=<nul>)
>[2014-08-28 10:24:28.474821] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-3 (hash=spacebar-replicate-16/cache=spacebar-replicate-7) => /f4-4 (hash=spacebar-replicate-2/cache=<nul>)
>[2014-08-28 10:24:39.872278] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-4 (hash=spacebar-replicate-2/cache=spacebar-replicate-7) => /f4-5 (hash=spacebar-replicate-3/cache=<nul>)
>[2014-08-28 10:24:50.740604] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-5 (hash=spacebar-replicate-3/cache=spacebar-replicate-7) => /f4-6 (hash=spacebar-replicate-11/cache=<nul>)
>[2014-08-28 10:25:01.914116] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-6 (hash=spacebar-replicate-11/cache=spacebar-replicate-7) => /f4-7 (hash=spacebar-replicate-2/cache=<nul>)
>[2014-08-28 10:25:13.393539] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-7 (hash=spacebar-replicate-2/cache=spacebar-replicate-7) => /f4-8 (hash=spacebar-replicate-6/cache=<nul>)
>[2014-08-28 10:25:24.881348] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-8 (hash=spacebar-replicate-6/cache=spacebar-replicate-7) => /f4-9 (hash=spacebar-replicate-4/cache=<nul>)
>[2014-08-28 10:25:36.013501] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-9 (hash=spacebar-replicate-4/cache=spacebar-replicate-7) => /f4-10 (hash=spacebar-replicate-2/cache=<nul>)
>[2014-08-28 10:25:47.287301] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-10 (hash=spacebar-replicate-2/cache=spacebar-replicate-7) => /f4-11 (hash=spacebar-replicate-13/cache=<nul>)
>[2014-08-28 10:25:58.588325] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-11 (hash=spacebar-replicate-13/cache=spacebar-replicate-7) => /f4-12 (hash=spacebar-replicate-0/cache=<nul>)
>[2014-08-28 10:26:11.492688] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-12 (hash=spacebar-replicate-0/cache=spacebar-replicate-7) => /f4-13 (hash=spacebar-replicate-11/cache=<nul>)
>[2014-08-28 10:26:22.762516] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-13 (hash=spacebar-replicate-11/cache=spacebar-replicate-7) => /f4-14 (hash=spacebar-replicate-9/cache=<nul>)
>[2014-08-28 10:26:34.104218] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-14 (hash=spacebar-replicate-9/cache=spacebar-replicate-7) => /f4-15 (hash=spacebar-replicate-4/cache=<nul>)
>[2014-08-28 10:26:45.275717] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-15 (hash=spacebar-replicate-4/cache=spacebar-replicate-7) => /f4-16 (hash=spacebar-replicate-5/cache=<nul>)
>[2014-08-28 10:26:57.004524] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-16 (hash=spacebar-replicate-5/cache=spacebar-replicate-7) => /f4-17 (hash=spacebar-replicate-6/cache=<nul>)
>[2014-08-28 10:27:08.649894] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-17 (hash=spacebar-replicate-6/cache=spacebar-replicate-7) => /f4-18 (hash=spacebar-replicate-21/cache=<nul>)
>[2014-08-28 10:27:09.257252] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-57 (hash=spacebar-replicate-19/cache=spacebar-replicate-19) => /test/f4-57 (hash=spacebar-replicate-5/cache=<nul>)
>[2014-08-28 10:27:16.054197] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-18 (hash=spacebar-replicate-21/cache=spacebar-replicate-7) => /f4-19 (hash=spacebar-replicate-23/cache=<nul>)
>[2014-08-28 10:27:18.215822] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /f4-19 (hash=spacebar-replicate-23/cache=spacebar-replicate-7) => /test/f4-19 (hash=spacebar-replicate-0/cache=<nul>)
>[2014-08-28 10:33:11.161611] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /test/f4-19 (hash=spacebar-replicate-0/cache=spacebar-replicate-7) => /test1/f4-19 (hash=spacebar-replicate-22/cache=<nul>)
>[2014-08-28 10:33:11.428847] D [MSGID: 0] [dht-rename.c:1281:dht_rename] 0-spacebar-dht: renaming /test/f4-57 (hash=spacebar-replicate-5/cache=spacebar-replicate-5) => /test1/f4-57 (hash=spacebar-replicate-18/cache=<nul>)
>
>NOTE: So there is no rename that stomps the sequence for f4-57, so both files survive. Same can be seen for the other files as well.
>

Actions: View

Attachments on bug 1136720: 937204