Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 937204 Details for
Bug 1136720
DHT + Rebalance + rename :- files are getting truncated after rename and rebalance
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
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:
Log snippets as discussed in Comment #3
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. >
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1136720
: 937204