Logs: Improved logs in lock/unlock execution path

Statedump will now start showing the lk-owner of the stack.

Change-Id: I9f650ce9a8b528cd626c8bb595c1bd1050462c86
BUG: 803209
Signed-off-by: Pranith Kumar K <pranithk@gluster.com>
Reviewed-on: http://review.gluster.com/2968
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Anand Avati <avati@redhat.com>

5 files changed, 14 insertions, 8 deletions

diff --git a/libglusterfs/src/stack.c b/libglusterfs/src/stack.c
index 787f9a318..6b852383a 100644
--- a/libglusterfs/src/stack.c
+++ b/libglusterfs/src/stack.c
@@ -109,6 +109,7 @@ gf_proc_dump_call_stack (call_stack_t *call_stack, const char *key_buf,...)
         gf_proc_dump_write("gid", "%d", call_stack->gid);
         gf_proc_dump_write("pid", "%d", call_stack->pid);
         gf_proc_dump_write("unique", "%Ld", call_stack->unique);
+        gf_proc_dump_write("lk-owner", "%s", lkowner_utoa (&call_stack->lk_owner));
 
         if (call_stack->type == GF_OP_TYPE_FOP)
                 gf_proc_dump_write("op", "%s", gf_fop_list[call_stack->op]);
diff --git a/xlators/cluster/afr/src/afr-lk-common.c b/xlators/cluster/afr/src/afr-lk-common.c
index aeac72d16..55dd60e88 100644
--- a/xlators/cluster/afr/src/afr-lk-common.c
+++ b/xlators/cluster/afr/src/afr-lk-common.c
@@ -714,7 +714,7 @@ afr_unlock_entrylk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                AFR_UNLOCK_OP, NULL, op_ret,
                                op_errno, child_index);
 
-        if (op_ret < 0 && op_errno != ENOTCONN && op_errno != EBADFD) {
+        if (op_ret < 0) {
                 gf_log (this->name, GF_LOG_ERROR,
                         "%s: unlock failed on %d, reason: %s",
                         local->loc.path, child_index, strerror (op_errno));
diff --git a/xlators/features/locks/src/inodelk.c b/xlators/features/locks/src/inodelk.c
index b8b5643e8..cbc9186aa 100644
--- a/xlators/features/locks/src/inodelk.c
+++ b/xlators/features/locks/src/inodelk.c
@@ -298,18 +298,22 @@ __inode_unlock_lock (xlator_t *this, pl_inode_lock_t *lock, pl_dom_list_t *dom)
 
         conf = find_matching_inodelk (lock, dom);
         if (!conf) {
-                gf_log (this->name, GF_LOG_DEBUG,
-                        " Matching lock not found for unlock");
+                gf_log (this->name, GF_LOG_ERROR,
+                        " Matching lock not found for unlock %llu-%llu, by %s "
+                        "on %p", (unsigned long long)lock->fl_start,
+                        (unsigned long long)lock->fl_end,
+                        lkowner_utoa (&lock->owner), lock->transport);
                 goto out;
         }
         __delete_inode_lock (conf);
         gf_log (this->name, GF_LOG_DEBUG,
-                " Matching lock found for unlock");
+                " Matching lock found for unlock %llu-%llu, by %s on %p",
+                (unsigned long long)lock->fl_start,
+                (unsigned long long)lock->fl_end, lkowner_utoa (&lock->owner),
+                lock->transport);
 
 out:
         return conf;
-
-
 }
 static void
 __grant_blocked_inode_locks (xlator_t *this, pl_inode_t *pl_inode,
diff --git a/xlators/protocol/server/src/server-handshake.c b/xlators/protocol/server/src/server-handshake.c
index d951aad9c..8478a27ba 100644
--- a/xlators/protocol/server/src/server-handshake.c
+++ b/xlators/protocol/server/src/server-handshake.c
@@ -431,6 +431,7 @@ server_setvolume (rpcsvc_request_t *req)
                 goto fail;
         }
 
+        gf_log (this->name, GF_LOG_DEBUG, "Connected to %s", conn->id);
         cancelled = server_cancel_conn_timer (this, conn);
         if (cancelled)//Do connection_put on behalf of grace-timer-handler.
                 server_connection_put (this, conn, NULL);
diff --git a/xlators/protocol/server/src/server.c b/xlators/protocol/server/src/server.c
index 3c3147a19..a29caa987 100644
--- a/xlators/protocol/server/src/server.c
+++ b/xlators/protocol/server/src/server.c
@@ -645,7 +645,7 @@ server_rpc_notify (rpcsvc_t *rpc, void *xl, rpcsvc_event_t event,
 
                 put_server_conn_state (this, xprt);
                 gf_log (this->name, GF_LOG_INFO, "disconnecting connection"
-                        "from %s", xprt->peerinfo.identifier);
+                        "from %s", conn->id);
                 server_connection_cleanup (this, conn, INTERNAL_LOCKS);
                 pthread_mutex_lock (&conf->mutex);
                 {
@@ -659,7 +659,7 @@ server_rpc_notify (rpcsvc_t *rpc, void *xl, rpcsvc_event_t event,
                                 goto unlock;
 
                         gf_log (this->name, GF_LOG_INFO, "starting a grace "
-                                "timer for %s", xprt->name);
+                                "timer for %s", conn->id);
 
                         conn->timer = gf_timer_call_after (this->ctx,
                                                            conf->grace_tv,