cluster/afr: Log errors in afr self-heal with GF_LOG_ERROR

Signed-off-by: Pranith Kumar K <pranithk@gluster.com>
Signed-off-by: Anand Avati <avati@gluster.com>

BUG: 2986 (Failed operations should should be logged `E' or `W')
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=2986

6 files changed, 57 insertions, 43 deletions

diff --git a/xlators/cluster/afr/src/afr-lk-common.c b/xlators/cluster/afr/src/afr-lk-common.c
index a134cd0df..65cfaf063 100644
--- a/xlators/cluster/afr/src/afr-lk-common.c
+++ b/xlators/cluster/afr/src/afr-lk-common.c
@@ -556,13 +556,17 @@ static int32_t
 afr_unlock_inodelk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                         int32_t op_ret, int32_t op_errno)
 {
+        afr_local_t *local = NULL;
+        local = frame->local;
+
         afr_trace_inodelk_out (frame, AFR_INODELK_TRANSACTION,
                                AFR_UNLOCK_OP, NULL, op_ret,
                                op_errno, (long) cookie);
 
         if (op_ret < 0 && op_errno != ENOTCONN && op_errno != EBADFD) {
-                gf_log (this->name, GF_LOG_TRACE,
-                        "Unlock failed for some reason");
+                gf_log (this->name, GF_LOG_ERROR,
+                         "%s: unlock failed %s",
+                         local->loc.path, strerror (op_errno));
         }
 
         afr_unlock_common_cbk (frame, cookie, this, op_ret, op_errno);
diff --git a/xlators/cluster/afr/src/afr-self-heal-algorithm.c b/xlators/cluster/afr/src/afr-self-heal-algorithm.c
index f72da7741..23012ac0e 100644
--- a/xlators/cluster/afr/src/afr-self-heal-algorithm.c
+++ b/xlators/cluster/afr/src/afr-self-heal-algorithm.c
@@ -161,7 +161,7 @@ sh_full_write_cbk (call_frame_t *rw_frame, void *cookie, xlator_t *this,
 	LOCK (&sh_frame->lock);
 	{
 		if (op_ret == -1) {
-			gf_log (this->name, GF_LOG_DEBUG,
+			gf_log (this->name, GF_LOG_ERROR,
 				"write to %s failed on subvolume %s (%s)",
 				sh_local->loc.path,
 				priv->children[child_index]->name,
@@ -218,6 +218,12 @@ sh_full_read_cbk (call_frame_t *rw_frame, void *cookie,
 		op_ret, sh_local->loc.path, offset);
 
 	if (op_ret <= 0) {
+                gf_log (this->name, GF_LOG_ERROR,
+                        "read from %s failed on subvolume %s (%s)",
+                        sh_local->loc.path,
+                        priv->children[sh->source]->name,
+                        strerror (op_errno));
+
                 sh->op_failed = 1;
                 sh_full_loop_return (rw_frame, this, offset);
 		return 0;
@@ -611,7 +617,7 @@ sh_diff_write_cbk (call_frame_t *rw_frame, void *cookie, xlator_t *this,
 	LOCK (&sh_frame->lock);
 	{
 		if (op_ret == -1) {
-			gf_log (this->name, GF_LOG_DEBUG,
+			gf_log (this->name, GF_LOG_ERROR,
 				"write to %s failed on subvolume %s (%s)",
 				sh_local->loc.path,
 				priv->children[child_index]->name,
diff --git a/xlators/cluster/afr/src/afr-self-heal-common.c b/xlators/cluster/afr/src/afr-self-heal-common.c
index 7ef4c508d..5a5326ee3 100644
--- a/xlators/cluster/afr/src/afr-self-heal-common.c
+++ b/xlators/cluster/afr/src/afr-self-heal-common.c
@@ -778,9 +778,10 @@ afr_sh_missing_entries_done (call_frame_t *frame, xlator_t *this)
 	}
 
 	if (local->govinda_gOvinda) {
-		gf_log (this->name, GF_LOG_TRACE,
-			"aborting selfheal of %s",
+		gf_log (this->name, GF_LOG_INFO,
+			"split brain found, aborting selfheal of %s",
 			local->loc.path);
+                sh->op_failed = 1;
 		sh->completion_cbk (frame, this);
 	} else {
 		gf_log (this->name, GF_LOG_TRACE,
@@ -1525,11 +1526,16 @@ afr_self_heal_completion_cbk (call_frame_t *bgsh_frame, xlator_t *this)
                                      _gf_false);
         }
 
-        afr_self_heal_type_str_get(sh, sh_type_str,
-                                   sizeof(sh_type_str));
-        gf_log (this->name, GF_LOG_NORMAL,
-                "background %s self-heal completed on %s", sh_type_str,
-                local->loc.path);
+        afr_self_heal_type_str_get (sh, sh_type_str,
+                                    sizeof(sh_type_str));
+        if (sh->op_failed) {
+                gf_log (this->name, GF_LOG_ERROR, "background %s self-heal "
+                        "failed on %s", sh_type_str, local->loc.path);
+        } else {
+                gf_log (this->name, GF_LOG_INFO, "background %s self-heal "
+                        "completed on %s", sh_type_str, local->loc.path);
+        }
+
         FRAME_SU_UNDO (bgsh_frame, afr_local_t);
 
         if (!sh->unwound) {
@@ -1649,7 +1655,7 @@ void
 afr_self_heal_type_str_get (afr_self_heal_t *self_heal_p, char *str,
                             size_t size)
 {
-        GF_ASSERT (str && (size > 0));
+        GF_ASSERT (str && (size > strlen (" meta-data data entry")));
 
         if (self_heal_p->need_metadata_self_heal) {
                 snprintf(str, size, " meta-data");
diff --git a/xlators/cluster/afr/src/afr-self-heal-data.c b/xlators/cluster/afr/src/afr-self-heal-data.c
index 0fd8dae69..263d49fbb 100644
--- a/xlators/cluster/afr/src/afr-self-heal-data.c
+++ b/xlators/cluster/afr/src/afr-self-heal-data.c
@@ -75,10 +75,6 @@ afr_sh_data_done (call_frame_t *frame, xlator_t *this)
 /*         for (i = 0; i < priv->child_count; i++) */
 /*                 sh->locked_nodes[i] = 0; */
 
-	gf_log (this->name, GF_LOG_TRACE,
-		"self heal of %s completed",
-		local->loc.path);
-
 	sh->completion_cbk (frame, this);
 
 	return 0;
@@ -912,18 +908,21 @@ afr_sh_data_post_nonblocking_inodelk_cbk (call_frame_t *frame, xlator_t *this)
 {
         afr_internal_lock_t *int_lock = NULL;
         afr_local_t         *local    = NULL;
+        afr_self_heal_t     *sh       = NULL;
 
         local    = frame->local;
         int_lock = &local->internal_lock;
+        sh       = &local->self_heal;
 
         if (int_lock->lock_op_ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking inodelks failed.");
+                gf_log (this->name, GF_LOG_ERROR, "Non Blocking data inodelks "
+                        "failed for %s.", local->loc.path);
+                sh->op_failed = 1;
                 afr_sh_data_done (frame, this);
         } else {
 
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking inodelks done. Proceeding to FOP");
+                gf_log (this->name, GF_LOG_DEBUG, "Non Blocking data inodelks "
+                        "done for %s. Proceeding to FOP", local->loc.path);
                 afr_sh_data_fxattrop (frame, this);
         }
 
@@ -953,7 +952,6 @@ afr_sh_data_lock_rec (call_frame_t *frame, xlator_t *this)
 
         afr_nonblocking_inodelk (frame, this);
 
-
 	return 0;
 }
 
@@ -1005,7 +1003,7 @@ afr_sh_data_open_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 	LOCK (&frame->lock);
 	{
 		if (op_ret == -1) {
-			gf_log (this->name, GF_LOG_TRACE,
+			gf_log (this->name, GF_LOG_ERROR,
 				"open of %s failed on child %s (%s)",
 				local->loc.path,
 				priv->children[child_index]->name,
diff --git a/xlators/cluster/afr/src/afr-self-heal-entry.c b/xlators/cluster/afr/src/afr-self-heal-entry.c
index 4a06019f7..c4e1532ba 100644
--- a/xlators/cluster/afr/src/afr-self-heal-entry.c
+++ b/xlators/cluster/afr/src/afr-self-heal-entry.c
@@ -75,10 +75,6 @@ afr_sh_entry_done (call_frame_t *frame, xlator_t *this)
 /*                 sh->locked_nodes[i] = 0; */
 /*         } */
 
-	gf_log (this->name, GF_LOG_TRACE,
-		"self heal of %s completed",
-		local->loc.path);
-
 	sh->completion_cbk (frame, this);
 
 	return 0;
@@ -1074,7 +1070,7 @@ afr_sh_entry_impunge_newfile_cbk (call_frame_t *impunge_frame, void *cookie,
 	child_index = (long) cookie;
 
 	if (op_ret == -1) {
-		gf_log (this->name, GF_LOG_DEBUG,
+		gf_log (this->name, GF_LOG_ERROR,
 			"creation of %s on %s failed (%s)",
 			impunge_local->loc.path,
 			priv->children[child_index]->name,
@@ -1948,7 +1944,7 @@ afr_sh_entry_opendir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 	LOCK (&frame->lock);
 	{
 		if (op_ret == -1) {
-			gf_log (this->name, GF_LOG_DEBUG,
+			gf_log (this->name, GF_LOG_ERROR,
 				"opendir of %s failed on child %s (%s)",
 				local->loc.path,
 				priv->children[child_index]->name,
@@ -2247,18 +2243,21 @@ afr_sh_post_nonblocking_entry_cbk (call_frame_t *frame, xlator_t *this)
 {
         afr_internal_lock_t *int_lock = NULL;
         afr_local_t         *local    = NULL;
+        afr_self_heal_t     *sh       = NULL;
 
         local    = frame->local;
         int_lock = &local->internal_lock;
+        sh       = &local->self_heal;
 
         if (int_lock->lock_op_ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking entrylks failed.");
+                gf_log (this->name, GF_LOG_ERROR, "Non Blocking entrylks "
+                        "failed for %s.", local->loc.path);
+                sh->op_failed = 1;
                 afr_sh_entry_done (frame, this);
         } else {
 
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking entrylks done. Proceeding to FOP");
+                gf_log (this->name, GF_LOG_DEBUG, "Non Blocking entrylks done "
+                        "for %s. Proceeding to FOP", local->loc.path);
                 afr_sh_entry_lookup(frame, this);
         }
 
diff --git a/xlators/cluster/afr/src/afr-self-heal-metadata.c b/xlators/cluster/afr/src/afr-self-heal-metadata.c
index e76d58850..ee4daf4b5 100644
--- a/xlators/cluster/afr/src/afr-self-heal-metadata.c
+++ b/xlators/cluster/afr/src/afr-self-heal-metadata.c
@@ -76,9 +76,10 @@ afr_sh_metadata_done (call_frame_t *frame, xlator_t *this)
 	}
 
 	if (local->govinda_gOvinda) {
-		gf_log (this->name, GF_LOG_DEBUG,
-			"aborting selfheal of %s",
+		gf_log (this->name, GF_LOG_INFO,
+			"split-brain detected, aborting selfheal of %s",
 			local->loc.path);
+                sh->op_failed = 1;
 		sh->completion_cbk (frame, this);
 	} else {
 		if (IA_ISREG (sh->type)) {
@@ -96,9 +97,6 @@ afr_sh_metadata_done (call_frame_t *frame, xlator_t *this)
 			afr_self_heal_entry (frame, this);
 			return 0;
 		}
-		gf_log (this->name, GF_LOG_DEBUG,
-			"completed self heal of %s",
-			local->loc.path);
 
 		sh->completion_cbk (frame, this);
 	}
@@ -664,7 +662,8 @@ afr_sh_metadata_lookup (call_frame_t *frame, xlator_t *this)
 }
 
 int
-afr_sh_post_nonblocking_inodelk_cbk (call_frame_t *frame, xlator_t *this)
+afr_sh_metadata_post_nonblocking_inodelk_cbk (call_frame_t *frame,
+                                              xlator_t *this)
 {
         afr_internal_lock_t *int_lock = NULL;
         afr_local_t         *local    = NULL;
@@ -673,13 +672,15 @@ afr_sh_post_nonblocking_inodelk_cbk (call_frame_t *frame, xlator_t *this)
         int_lock = &local->internal_lock;
 
         if (int_lock->lock_op_ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking inodelks failed.");
+                gf_log (this->name, GF_LOG_ERROR, "Non Blocking metadata "
+                        "inodelks failed for %s. Metadata self-heal "
+                        "failed", local->loc.path);
                 afr_sh_metadata_done (frame, this);
         } else {
 
-                gf_log (this->name, GF_LOG_DEBUG,
-                        "Non Blocking inodelks done. Proceeding to FOP");
+                gf_log (this->name, GF_LOG_DEBUG, "Non Blocking metadata "
+                        "inodelks done for %s. Proceeding to FOP",
+                        local->loc.path);
                 afr_sh_metadata_lookup (frame, this);
         }
 
@@ -703,7 +704,7 @@ afr_sh_metadata_lock (call_frame_t *frame, xlator_t *this)
         int_lock->lk_flock.l_start = 0;
         int_lock->lk_flock.l_len   = 0;
         int_lock->lk_flock.l_type  = F_WRLCK;
-        int_lock->lock_cbk         = afr_sh_post_nonblocking_inodelk_cbk;
+        int_lock->lock_cbk         = afr_sh_metadata_post_nonblocking_inodelk_cbk;
 
         afr_nonblocking_inodelk (frame, this);