1240925 – Data Tiering: file marked for demotion is getting demoted even if the file is being accessed( a heating operation)

Bug 1240925 - Data Tiering: file marked for demotion is getting demoted even if the file is being accessed( a heating operation)

Summary: Data Tiering: file marked for demotion is getting demoted even if the file is...

Keywords:
Status:	CLOSED DUPLICATE of bug 1273347
Alias:	None
Product:	Red Hat Gluster Storage
Classification:	Red Hat Storage
Component:	tier
Sub Component:
Version:	rhgs-3.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	urgent
Severity:	urgent
Target Milestone:	---
Target Release:	---
Assignee:	Joseph Elwin Fernandes
QA Contact:	Nag Pavan Chilakam
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1202842
TreeView+	depends on / blocked

Reported:	2015-07-08 07:19 UTC by Nag Pavan Chilakam
Modified:	2016-09-17 15:38 UTC (History)
CC List:	6 users (show)
Fixed In Version:	glusterfs-3.7.1-9
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2015-12-22 08:53:42 UTC
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Description Nag Pavan Chilakam 2015-07-08 07:19:38 UTC

Description:
============
When I file in hot tier is idle for sometime, it is marked for demotion. But before the demote happens, if the file is accessed again, by say reading the file or changing file metadata, then the file ideally should continue to stay in hot tier. But this is not the case. It is currently getting demoted, once marked for demotion irrespective of file being re-accessed or not

Steps:
=====
A file marked for demotion is getting demoted even if the file is being accessed:
1) i created a hot file as below
[root@rhs-client6 vol2]# touch xyz
[root@rhs-client6 vol2]# stat xyz
  File: `xyz'
  Size: 0         	Blocks: 0          IO Block: 1048576 regular empty file
Device: 1bh/27d	Inode: 13353154674754277901  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2015-07-08 01:25:09.000000000 +0530
Modify: 2015-07-08 01:25:09.000000000 +0530
Change: 2015-07-08 01:25:09.097999988 +0530
2)checked backend brick, file was in hot tier and epoch was stamped
[root@nchilaka-tier03 ~]# echo "== c1 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick1/vol2/.glusterfs/vol2.db; echo "== c2 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick2/vol2/.glusterfs/vol2.db; echo "== h1 ==" ; echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick3/vol2/.glusterfs/vol2.db
== c1 ==
Error: unable to open database "/rhs/brick1/vol2/.glusterfs/vol2.db": unable to open database file
== c2 ==
Error: unable to open database "/rhs/brick2/vol2/.glusterfs/vol2.db": unable to open database file
== h1 ==
68ab61db-c15f-497c-b94f-ef6dbb93520d|1436298909|97064|0|0|0|0|0|0|1|1
68ab61db-c15f-497c-b94f-ef6dbb93520d|00000000-0000-0000-0000-000000000001|xyz|/xyz|0|0


3)used touch to re-access file again after 30 sec
[root@rhs-client6 vol2]# touch xyz
[root@rhs-client6 vol2]# stat xyz
  File: `xyz'
  Size: 0         	Blocks: 0          IO Block: 1048576 regular empty file
Device: 1bh/27d	Inode: 13353154674754277901  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2015-07-08 01:25:38.000000000 +0530
Modify: 2015-07-08 01:25:38.000000000 +0530
Change: 2015-07-08 01:25:38.882000001 +0530

4)saw brickend and ctime was stamped successfully as below
[root@nchilaka-tier03 ~]# echo "== c1 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick1/vol2/.glusterfs/vol2.db; echo "== c2 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick2/vol2/.glusterfs/vol2.db; echo "== h1 ==" ; echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick3/vol2/.glusterfs/vol2.db
== c1 ==
Error: unable to open database "/rhs/brick1/vol2/.glusterfs/vol2.db": unable to open database file
== c2 ==
Error: unable to open database "/rhs/brick2/vol2/.glusterfs/vol2.db": unable to open database file
== h1 ==
68ab61db-c15f-497c-b94f-ef6dbb93520d|1436298938|880419|0|0|0|0|0|0|1|1
68ab61db-c15f-497c-b94f-ef6dbb93520d|00000000-0000-0000-0000-000000000001|xyz|/xyz|0|0


5)HOWEVER, Now within a few seconds  the file got demoted (below was the ctime)
[root@rhs-client6 vol2]# stat xyz
  File: `xyz'
  Size: 0         	Blocks: 0          IO Block: 1048576 regular empty file
Device: 1bh/27d	Inode: 13353154674754277901  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2015-07-08 01:25:38.000000000 +0530
Modify: 2015-07-08 01:25:38.000000000 +0530
Change: 2015-07-08 01:26:00.583000149 +0530


6)brick backend
[root@nchilaka-tier01 ~]# echo "== c1 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick1/vol2/.glusterfs/vol2.db; echo "== c2 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick2/vol2/.glusterfs/vol2.db; echo "== h1 ==" ; echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick3/vol2/.glusterfs/vol2.db
== c1 ==
== c2 ==
52ef1723-f985-4d47-9f6f-0fd302e3553d|0|0|0|0|0|0|0|0|1|1
68ab61db-c15f-497c-b94f-ef6dbb93520d|0|0|0|0|0|0|0|0|1|1
90bc6ab0-e836-415f-940a-c955b2a4544c|0|0|0|0|0|0|0|0|1|1
52ef1723-f985-4d47-9f6f-0fd302e3553d|00000000-0000-0000-0000-000000000001|f1|/f1|0|0
68ab61db-c15f-497c-b94f-ef6dbb93520d|00000000-0000-0000-0000-000000000001|xyz|/xyz|0|0
90bc6ab0-e836-415f-940a-c955b2a4544c|00000000-0000-0000-0000-000000000001|newnew|/newnew|0|0
== h1 ==
[root@nchilaka-tier01 ~]# 

[root@nchilaka-tier03 ~]# echo "== c1 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick1/vol2/.glusterfs/vol2.db; echo "== c2 ==" ;  echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick2/vol2/.glusterfs/vol2.db; echo "== h1 ==" ; echo "select * from gf_file_tb; select * from gf_flink_tb;" | sqlite3 /rhs/brick3/vol2/.glusterfs/vol2.db
== c1 ==
Error: unable to open database "/rhs/brick1/vol2/.glusterfs/vol2.db": unable to open database file
== c2 ==
Error: unable to open database "/rhs/brick2/vol2/.glusterfs/vol2.db": unable to open database file
== h1 ==
[root@nchilaka-tier03 ~]# 






####################
Tiering reblancer logs


[root@nchilaka-tier03 glusterfs]# ########################################
[root@nchilaka-tier03 glusterfs]# ########################################
[root@nchilaka-tier03 glusterfs]# ########################################
[root@nchilaka-tier03 glusterfs]# ########################################
[root@nchilaka-tier03 glusterfs]# tail -f vol2-tier.log
[2015-07-07 19:32:00.967420] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:32:00.967534] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:32:00.968528] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
########deleted all files #############
[2015-07-07 19:32:58.421870] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89069.00 secs
[2015-07-07 19:32:58.421942] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 26, size: 0, lookups: 27, failures: 1, skipped: 0
[2015-07-07 19:33:11.970021] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89082.00 secs
[2015-07-07 19:33:12.222025] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89083.00 secs
[2015-07-07 19:33:48.813434] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89119.00 secs
The message "I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 26, size: 0, lookups: 27, failures: 1, skipped: 0" repeated 3 times between [2015-07-07 19:32:58.421942] and [2015-07-07 19:33:48.813561]
[2015-07-07 19:33:49.094588] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89120.00 secs
[2015-07-07 19:33:49.094739] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 26, size: 0, lookups: 27, failures: 1, skipped: 0
[2015-07-07 19:34:00.981909] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:34:00.982043] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:34:00.984646] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file f1
[2015-07-07 19:34:00.985517] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /f1: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:34:00.998607] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:34:00.998702] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:34:00.998997] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /f1: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:34:01.031010] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /f1 from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:34:01.031799] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
#######created file f1############
[2015-07-07 19:34:55.168130] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89186.00 secs
[2015-07-07 19:34:55.168185] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 27, size: 0, lookups: 28, failures: 1, skipped: 0
[2015-07-07 19:36:00.047138] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:36:00.047231] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:36:00.048014] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:34:55.404911] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89186.00 secs
[2015-07-07 19:34:55.404915] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 27, size: 0, lookups: 28, failures: 1, skipped: 0
[2015-07-07 19:38:00.060926] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:38:00.061097] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:38:00.062975] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:38:47.855203] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89418.00 secs
[2015-07-07 19:38:47.855383] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 27, size: 0, lookups: 28, failures: 1, skipped: 0
[2015-07-07 19:38:48.081794] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89419.00 secs
[2015-07-07 19:40:00.077018] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:40:00.077103] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:40:00.078110] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:38:48.081922] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 27, size: 0, lookups: 28, failures: 1, skipped: 0
[2015-07-07 19:42:00.091865] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:42:00.091960] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:42:00.094502] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file f1
[2015-07-07 19:42:00.095208] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /f1: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:42:00.108946] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:42:00.109035] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:42:00.109545] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /f1: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:42:00.147199] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /f1 from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:42:00.148794] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:44:00.161117] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:44:00.161200] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:44:00.162053] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:46:00.173749] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:46:00.173838] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:46:00.174854] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:48:00.188318] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:48:00.188476] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:48:00.190805] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file f1
[2015-07-07 19:48:00.191778] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /f1: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:48:00.200294] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:48:00.200387] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:48:00.200686] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /f1: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:48:00.230904] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /f1 from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:48:00.231830] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:50:00.246291] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:50:00.246492] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:50:00.247128] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:52:00.260568] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:52:00.260683] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:52:00.261636] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:54:00.273972] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:54:00.274134] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:54:00.276288] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file newnew
[2015-07-07 19:54:00.277311] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /newnew: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:54:00.284817] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:54:00.284820] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:54:00.285127] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /newnew: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:54:00.310826] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /newnew from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:54:00.311582] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:56:00.326270] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:56:00.326356] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:56:00.328671] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file xyz
[2015-07-07 19:56:00.329502] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /xyz: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:56:00.338673] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:56:00.338809] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:56:00.339200] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /xyz: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:56:00.370221] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /xyz	 from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:56:00.372545] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 0 src_subvol vol2-hot-dht file newnew
[2015-07-07 19:56:00.374297] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /newnew: attempting to move from vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:56:00.382836] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-2: remote operation failed [Permission denied]
[2015-07-07 19:56:00.382904] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-3: remote operation failed [Permission denied]
[2015-07-07 19:56:00.383281] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /newnew: failed to set xattr on vol2-cold-dht (Permission denied)
[2015-07-07 19:56:00.412371] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /newnew from subvolume vol2-hot-dht to vol2-cold-dht
[2015-07-07 19:56:00.413245] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:58:00.424964] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 19:58:00.425047] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 19:58:00.426146] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 20:00:00.438396] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 20:00:00.438488] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 20:00:00.439240] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 20:02:00.531611] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 20:02:00.531727] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 20:02:00.532694] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 20:04:00.546901] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6709
[2015-07-07 20:04:00.546984] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/promotequeryfile-6709 for migration
[2015-07-07 20:04:00.547872] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!







[root@nchilaka-tier01 glusterfs]# ########################################
[root@nchilaka-tier01 glusterfs]# ########################################
[root@nchilaka-tier01 glusterfs]# ########################################
[root@nchilaka-tier01 glusterfs]# ########################################
[root@nchilaka-tier01 glusterfs]# tail -f vol2-tier.log
########deleted all files #############
[2015-07-07 19:32:58.639229] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89069.00 secs
[2015-07-07 19:32:58.639314] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0
[2015-07-07 19:33:12.187151] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89083.00 secs
[2015-07-07 19:33:49.032889] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89120.00 secs
#######created file f1############
[2015-07-07 19:33:12.438199] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89083.00 secs
[2015-07-07 19:33:49.311872] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89120.00 secs
The message "I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0" repeated 4 times between [2015-07-07 19:32:58.639314] and [2015-07-07 19:33:49.311875]
[2015-07-07 19:34:55.386510] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89186.00 secs
[2015-07-07 19:34:55.386576] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0
[2015-07-07 19:34:55.623864] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89186.00 secs
[2015-07-07 19:34:55.623867] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0
[2015-07-07 19:38:48.072710] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89419.00 secs
[2015-07-07 19:38:48.072768] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0
[2015-07-07 19:40:00.843725] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file f1
[2015-07-07 19:40:00.844920] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /f1: attempting to move from vol2-cold-dht to vol2-hot-dht
[2015-07-07 19:40:00.855922] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-5: remote operation failed [Permission denied]
[2015-07-07 19:40:00.856003] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /f1: failed to set xattr on vol2-hot-dht (Permission denied)
[2015-07-07 19:40:00.890948] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /f1 from subvolume vol2-cold-dht to vol2-hot-dht
[2015-07-07 19:38:48.300146] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89419.00 secs
[2015-07-07 19:38:48.300150] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 37, size: 0, lookups: 37, failures: 0, skipped: 0
[2015-07-07 19:46:00.931646] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file f1
[2015-07-07 19:46:00.932667] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /f1: attempting to move from vol2-cold-dht to vol2-hot-dht
[2015-07-07 19:46:00.939392] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-5: remote operation failed [Permission denied]
[2015-07-07 19:46:00.939492] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /f1: failed to set xattr on vol2-hot-dht (Permission denied)
[2015-07-07 19:46:00.968211] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /f1 from subvolume vol2-cold-dht to vol2-hot-dht
[2015-07-07 19:56:00.021155] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file newnew
[2015-07-07 19:56:00.022004] I [dht-rebalance.c:1002:dht_migrate_file] 0-vol2-tier-dht: /newnew: attempting to move from vol2-cold-dht to vol2-hot-dht
[2015-07-07 19:56:00.029370] W [MSGID: 114031] [client-rpc-fops.c:1977:client3_3_fsetxattr_cbk] 0-vol2-client-5: remote operation failed [Permission denied]
[2015-07-07 19:56:00.029449] W [MSGID: 109023] [dht-rebalance.c:546:__dht_rebalance_create_dst_file] 0-vol2-tier-dht: /newnew: failed to set xattr on vol2-hot-dht (Permission denied)
[2015-07-07 19:56:00.060819] I [MSGID: 109022] [dht-rebalance.c:1282:dht_migrate_file] 0-vol2-tier-dht: completed migration of /newnew from subvolume vol2-cold-dht to vol2-hot-dht



[root@nchilaka-tier02 glusterfs]# ########################################
[root@nchilaka-tier02 glusterfs]# ########################################
[root@nchilaka-tier02 glusterfs]# ########################################
[root@nchilaka-tier02 glusterfs]# ########################################
[root@nchilaka-tier02 glusterfs]# tail -f vol2-tier.log
[2015-07-07 19:32:00.080967] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:32:00.081057] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:32:00.081121] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
########deleted all files #############
[2015-07-07 19:32:58.954230] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89068.00 secs
[2015-07-07 19:32:58.954307] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0
[2015-07-07 19:33:12.502584] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89082.00 secs
[2015-07-07 19:33:49.345711] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89119.00 secs
[2015-07-07 19:34:00.094622] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:34:00.094711] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:34:00.094767] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
#######created file f1############
[2015-07-07 19:33:12.753532] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89082.00 secs
[2015-07-07 19:33:49.627265] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89119.00 secs
The message "I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0" repeated 4 times between [2015-07-07 19:32:58.954307] and [2015-07-07 19:33:49.627268]
[2015-07-07 19:34:55.699793] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89185.00 secs
[2015-07-07 19:34:55.699856] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0
[2015-07-07 19:36:00.108488] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:36:00.108650] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:36:00.108773] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:34:55.936619] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89185.00 secs
[2015-07-07 19:34:55.936622] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0
[2015-07-07 19:38:00.122471] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:38:00.122588] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:38:00.122698] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:38:48.385543] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89418.00 secs
[2015-07-07 19:38:48.385595] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0
[2015-07-07 19:40:00.138322] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:40:00.138515] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:40:00.138643] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:40:00.148329] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file f1
[2015-07-07 19:40:00.148938] I [MSGID: 109038] [tier.c:109:tier_check_same_node] 0-vol2-tier-dht: /f1 does not belong to this node
[2015-07-07 19:40:00.149330] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:38:48.615115] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 89418.00 secs
[2015-07-07 19:38:48.615118] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 22, failures: 22, skipped: 0
[2015-07-07 19:42:00.162120] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:42:00.162136] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6736
[2015-07-07 19:42:00.162471] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:42:00.162615] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:44:00.178019] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:44:00.178118] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:44:00.178182] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:46:00.192907] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:46:00.193013] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:46:00.193077] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:46:00.198343] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file f1
[2015-07-07 19:46:00.198752] I [MSGID: 109038] [tier.c:109:tier_check_same_node] 0-vol2-tier-dht: /f1 does not belong to this node
[2015-07-07 19:46:00.198989] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:48:00.212514] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6736
[2015-07-07 19:48:00.212514] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:48:00.212662] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:48:00.212750] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:50:00.229031] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:50:00.229138] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:50:00.229285] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:52:00.242040] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:52:00.242198] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:52:00.242369] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:54:00.256207] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:54:00.256336] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:54:00.256428] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:56:00.270555] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:56:00.270645] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:56:00.270707] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 19:56:00.276106] I [MSGID: 109038] [tier.c:350:tier_migrate_using_query_file] 0-vol2-tier-dht: Tier 1 src_subvol vol2-cold-dht file newnew
[2015-07-07 19:56:00.276498] I [MSGID: 109038] [tier.c:109:tier_check_same_node] 0-vol2-tier-dht: /newnew does not belong to this node
[2015-07-07 19:56:00.276751] E [MSGID: 109037] [tier.c:908:tier_start] 0-vol2-tier-dht: Promotion failed!
[2015-07-07 19:58:00.291193] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 19:58:00.291327] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 19:58:00.291225] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/promotequeryfile-6736
[2015-07-07 19:58:00.291475] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 20:00:00.306421] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 20:00:00.306515] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 20:00:00.306574] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 20:02:00.319567] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 20:02:00.319670] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 20:02:00.319726] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!
[2015-07-07 20:04:00.335432] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol2-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-6736
[2015-07-07 20:04:00.335522] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-6736 for migration
[2015-07-07 20:04:00.335590] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol2-tier-dht: Demotion failed!

Comment 2 Nag Pavan Chilakam 2015-07-08 07:21:12 UTC

Raised an upstream bug for upstream tracking 1240926

Comment 3 Nag Pavan Chilakam 2015-07-08 07:24:47 UTC

sosreports at rhsqe-repo:/home/repo/sosreports/bug.1240925

Comment 6 Joseph Elwin Fernandes 2015-07-10 05:13:22 UTC

https://code.engineering.redhat.com/gerrit/#/c/52745/

Comment 8 Nag Pavan Chilakam 2015-07-15 14:49:28 UTC

Crash seen 
0
[2015-07-15 19:30:00.791978] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol1-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-20722
[2015-07-15 19:30:00.792157] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-20722 for migration
[2015-07-15 19:30:00.792314] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol1-tier-dht: Demotion failed!
[2015-07-15 19:30:51.251535] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 3717.00 secs
[2015-07-15 19:30:51.251645] I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 1, failures: 1, skipped: 0
[2015-07-15 19:31:55.603263] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 3781.00 secs
[2015-07-15 19:32:00.547529] I [MSGID: 109028] [dht-rebalance.c:3029:gf_defrag_status_get] 0-glusterfs: Rebalance is in progress. Time taken is 3786.00 secs
[2015-07-15 19:32:00.812843] I [MSGID: 109038] [tier.c:572:tier_build_migration_qfile] 0-vol1-tier-dht: Failed to remove /var/run/gluster/demotequeryfile-20722
[2015-07-15 19:32:00.813010] E [MSGID: 109051] [tier.c:614:tier_migrate_files_using_qfile] 0-tier: Failed opening /var/run/gluster/demotequeryfile-20722 for migration
[2015-07-15 19:32:00.813204] E [MSGID: 109037] [tier.c:898:tier_start] 0-vol1-tier-dht: Demotion failed!
The message "I [MSGID: 109028] [dht-rebalance.c:3033:gf_defrag_status_get] 0-glusterfs: Files migrated: 0, size: 0, lookups: 1, failures: 1, skipped: 0" repeated 2 times between [2015-07-15 19:30:51.251645] and [2015-07-15 19:32:00.547674]
pending frames:
frame : type(0) op(0)
frame : type(0) op(0)
frame : type(0) op(0)
patchset: git://git.gluster.com/glusterfs.git
signal received: 11
time of crash: 
2015-07-15 19:32:00
configuration details:
argp 1
backtrace 1
dlfcn 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.7.1
/usr/lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb6)[0x7f1ef2f408e6]
/usr/lib64/libglusterfs.so.0(gf_print_trace+0x33f)[0x7f1ef2f604af]
/lib64/libc.so.6(+0x36ede326a0)[0x7f1ef18df6a0]
/lib64/libc.so.6(+0x36edf336ef)[0x7f1ef19e06ef]
/usr/lib64/libgfdb.so.0(gf_sql_query_function+0xdf)[0x7f1ee40e1dff]
/usr/lib64/libgfdb.so.0(gf_sqlite3_find_recently_changed_files+0xd5)[0x7f1ee40e5445]
/usr/lib64/libgfdb.so.0(find_recently_changed_files+0x4f)[0x7f1ee40e0def]
/usr/lib64/glusterfs/3.7.1/xlator/cluster/tier.so(+0x54305)[0x7f1ee5122305]
/usr/lib64/libglusterfs.so.0(dict_foreach_match+0x74)[0x7f1ef2f38234]
/usr/lib64/libglusterfs.so.0(dict_foreach+0x18)[0x7f1ef2f382e8]
/usr/lib64/glusterfs/3.7.1/xlator/cluster/tier.so(+0x55f9e)[0x7f1ee5123f9e]
/lib64/libpthread.so.0(+0x36ee207a51)[0x7f1ef202ba51]
/lib64/libc.so.6(clone+0x6d)[0x7f1ef199596d]
---------
^C
[root@nchilaka-tier-02 glusterfs]# 
[root@nchilaka-tier-02 glusterfs]# 
[root@nchilaka-tier-02 glusterfs]# 
[root@nchilaka-tier-02 glusterfs]# 
[root@nchilaka-tier-02 glusterfs]# 
[root@nchilaka-tier-02 glusterfs]# tail  vol1-tier.log 
/usr/lib64/libgfdb.so.0(gf_sql_query_function+0xdf)[0x7f1ee40e1dff]
/usr/lib64/libgfdb.so.0(gf_sqlite3_find_recently_changed_files+0xd5)[0x7f1ee40e5445]
/usr/lib64/libgfdb.so.0(find_recently_changed_files+0x4f)[0x7f1ee40e0def]
/usr/lib64/glusterfs/3.7.1/xlator/cluster/tier.so(+0x54305)[0x7f1ee5122305]
/usr/lib64/libglusterfs.so.0(dict_foreach_match+0x74)[0x7f1ef2f38234]
/usr/lib64/libglusterfs.so.0(dict_foreach+0x18)[0x7f1ef2f382e8]
/usr/lib64/glusterfs/3.7.1/xlator/cluster/tier.so(+0x55f9e)[0x7f1ee5123f9e]
/lib64/libpthread.so.0(+0x36ee207a51)[0x7f1ef202ba51]
/lib64/libc.so.6(clone+0x6d)[0x7f1ef199596d]

Comment 9 Nag Pavan Chilakam 2015-07-16 05:43:27 UTC

Moving to failed_qa as crash was observed and tier rebalance failed.
steps:
1)created a volume and set following options
performance.io-cache: off
performance.quick-read: off

2)atached tier and set following
features.ctr-enabled: on

3)Now mounted on nfs
4)created a zero byte file
5)got demoted after some time due to idleness
6)touched the file to heat it and also created another file and kept writing to this file as below
[root@nchilaka-nfs-client-6 vol1]# 
[root@nchilaka-nfs-client-6 vol1]# ########file seems to have got demoted...checking ctim########
[root@nchilaka-nfs-client-6 vol1]# stat hf1
  File: `hf1'
  Size: 0         	Blocks: 0          IO Block: 1048576 regular empty file
Device: 15h/21d	Inode: 13574446887746474160  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2015-07-16 00:01:19.000000000 +0530
Modify: 2015-07-16 00:01:19.000000000 +0530
Change: 2015-07-16 00:04:00.545000003 +0530
[root@nchilaka-nfs-client-6 vol1]# 
[root@nchilaka-nfs-client-6 vol1]# 
[root@nchilaka-nfs-client-6 vol1]# ###############now touching hf1########## and also creating a new file writing to it continurouslyu############
[root@nchilaka-nfs-client-6 vol1]# touch hf1
[root@nchilaka-nfs-client-6 vol1]# touch hf1
[root@nchilaka-nfs-client-6 vol1]# touch hf1
[root@nchilaka-nfs-client-6 vol1]# stat hf1
  File: `hf1'
  Size: 0         	Blocks: 0          IO Block: 1048576 regular empty file
Device: 15h/21d	Inode: 13574446887746474160  Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2015-07-16 00:06:15.000000000 +0530
Modify: 2015-07-16 00:06:15.000000000 +0530
Change: 2015-07-16 00:06:15.668999992 +0530
[root@nchilaka-nfs-client-6 vol1]# touch hf2
[root@nchilaka-nfs-client-6 vol1]# for i in {1..300};do echo "$i:hello">> hf2;sleep 2;done
^C
[root@nchilaka-nfs-client-6 vol1]# sleep 70;for i in {1..300};do echo "$i:newnenwwnw .. hello">> hf2;sleep 115;done
^C
[root@nchilaka-nfs-client-6 vol1]# 




Saw the crash.

Tested on the build version glusterfs-3.7.1-9



Logs are attached

Comment 10 Joseph Elwin Fernandes 2015-07-16 05:49:19 UTC

Could you please share the sos reports

Comment 11 Joseph Elwin Fernandes 2015-07-16 06:04:11 UTC

I need to look into the crash as a crash could have happened because of other issues also. Please share the complete sos report

Comment 12 Nag Pavan Chilakam 2015-07-16 07:07:14 UTC

sos reports @ rhsqe-repo.lab.eng.blr.redhat.com:/home/repo/sosreports/bug.1240925/failed_qa

Comment 16 Joseph Elwin Fernandes 2015-12-22 08:53:42 UTC


*** This bug has been marked as a duplicate of bug 1273347 ***

Note You need to log in before you can comment on or make changes to this bug.