protocol/client: log enhancement

Signed-off-by: Amar Tumballi <amar@gluster.com>
Signed-off-by: Vijay Bellur <vijay@dev.gluster.com>

BUG: 2346 (Log message enhancements in GlusterFS - phase 1)
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=2346

1 files changed, 151 insertions, 79 deletions

diff --git a/xlators/protocol/client/src/client-handshake.c b/xlators/protocol/client/src/client-handshake.c
index 4577dda5d65..b5c894fdcff 100644
--- a/xlators/protocol/client/src/client-handshake.c
+++ b/xlators/protocol/client/src/client-handshake.c
@@ -56,20 +56,25 @@ rpc_client_ping_timer_expired (void *data)
         this = data;
 
         if (!this || !this->private) {
+                gf_log ("", GF_LOG_WARNING, "xlator initialization not done");
                 goto out;
         }
 
         conf = this->private;
 
         clnt = conf->rpc;
-        if (!clnt)
+        if (!clnt) {
+                gf_log (this->name, GF_LOG_WARNING, "rpc not initialized");
                 goto out;
+        }
 
         conn = &clnt->conn;
         trans = conn->trans;
 
-        if (!trans)
+        if (!trans) {
+                gf_log (this->name, GF_LOG_WARNING, "transport not initialized");
                 goto out;
+        }
 
         pthread_mutex_lock (&conn->lock);
         {
@@ -97,8 +102,8 @@ rpc_client_ping_timer_expired (void *data)
                                                      rpc_client_ping_timer_expired,
                                                      (void *) this);
                         if (conn->ping_timer == NULL)
-                                gf_log (trans->name, GF_LOG_DEBUG,
-                                        "unable to setup timer");
+                                gf_log (trans->name, GF_LOG_WARNING,
+                                        "unable to setup ping timer");
 
                 } else {
                         conn->ping_started = 0;
@@ -109,8 +114,8 @@ rpc_client_ping_timer_expired (void *data)
         pthread_mutex_unlock (&conn->lock);
 
         if (disconnect) {
-                gf_log (trans->name, GF_LOG_ERROR,
-                        "Server %s has not responded in the last %d "
+                gf_log (trans->name, GF_LOG_CRITICAL,
+                        "server %s has not responded in the last %d "
                         "seconds, disconnecting.",
                         conn->trans->peerinfo.identifier,
                         conf->opt.ping_timeout);
@@ -134,17 +139,22 @@ client_start_ping (void *data)
         int                      frame_count = 0;
 
         this = data;
-        if (!this || !this->private)
+        if (!this || !this->private) {
+                gf_log ("", GF_LOG_WARNING, "xlator not initialized");
                 goto fail;
+        }
 
         conf  = this->private;
-        if (!conf->rpc)
+        if (!conf->rpc) {
+                gf_log (this->name, GF_LOG_WARNING, "rpc not initialized");
                 goto fail;
-
+        }
         conn = &conf->rpc->conn;
 
-        if (conf->opt.ping_timeout == 0)
+        if (conf->opt.ping_timeout == 0) {
+                gf_log (this->name, GF_LOG_INFO, "ping timeout is 0, returning");
                 return;
+        }
 
         pthread_mutex_lock (&conn->lock);
         {
@@ -163,12 +173,17 @@ client_start_ping (void *data)
                         /* using goto looked ugly here,
                          * hence getting out this way */
                         /* unlock */
+                        gf_log (this->name, GF_LOG_DEBUG,
+                                "returning as transport is already disconnected"
+                                " OR there are no frames (%d || %d)",
+                                frame_count, !conn->connected);
+
                         pthread_mutex_unlock (&conn->lock);
                         return;
                 }
 
                 if (frame_count < 0) {
-                        gf_log (this->name, GF_LOG_DEBUG,
+                        gf_log (this->name, GF_LOG_WARNING,
                                 "saved_frames->count is %"PRId64,
                                 conn->saved_frames->count);
                         conn->saved_frames->count = 0;
@@ -183,8 +198,8 @@ client_start_ping (void *data)
                                              (void *) this);
 
                 if (conn->ping_timer == NULL) {
-                        gf_log (this->name, GF_LOG_DEBUG,
-                                "unable to setup timer");
+                        gf_log (this->name, GF_LOG_WARNING,
+                                "unable to setup ping timer");
                 } else {
                         conn->ping_started = 1;
                 }
@@ -203,6 +218,7 @@ client_start_ping (void *data)
 
         return;
 fail:
+        gf_log ("", GF_LOG_ERROR, "failed to start ping timer");
 
         if (frame) {
                 STACK_DESTROY (frame->root);
@@ -222,28 +238,31 @@ client_ping_cbk (struct rpc_req *req, struct iovec *iov, int count,
         call_frame_t          *frame   = NULL;
         clnt_conf_t           *conf    = NULL;
 
-        if (!myframe)
+        if (!myframe) {
+                gf_log ("", GF_LOG_WARNING, "frame with the request is NULL");
                 goto out;
-
+        }
         frame = myframe;
         this = frame->this;
-        if (!this || !this->private)
+        if (!this || !this->private) {
+                gf_log ("", GF_LOG_WARNING, "xlator private is not set");
                 goto out;
+        }
 
         conf = this->private;
         conn = &conf->rpc->conn;
 
         if (req->rpc_status == -1) {
-		 if (conn->ping_timer != NULL) {
-			 gf_log (this->name, GF_LOG_DEBUG, "socket or ib"
-				 " related error");
-			 gf_timer_call_cancel (this->ctx, conn->ping_timer);
-			 conn->ping_timer = NULL;
-		 } else {
-			 /* timer expired and transport bailed out */
-			 gf_log (this->name, GF_LOG_DEBUG, "timer must have "
-			 "expired");
-		 }
+                if (conn->ping_timer != NULL) {
+                        gf_log (this->name, GF_LOG_WARNING, "socket or ib"
+                                " related error");
+                        gf_timer_call_cancel (this->ctx, conn->ping_timer);
+                        conn->ping_timer = NULL;
+                } else {
+                        /* timer expired and transport bailed out */
+                        gf_log (this->name, GF_LOG_WARNING, "timer must have "
+                                "expired");
+                }
                 goto out;
         }
 
@@ -260,8 +279,8 @@ client_ping_cbk (struct rpc_req *req, struct iovec *iov, int count,
                                              client_start_ping, (void *)this);
 
                 if (conn->ping_timer == NULL)
-                        gf_log (this->name, GF_LOG_DEBUG,
-                                "gf_timer_call_after() returned NULL");
+                        gf_log (this->name, GF_LOG_WARNING,
+                                "failed to set the ping timer");
         }
         pthread_mutex_unlock (&conn->lock);
 out:
@@ -281,22 +300,32 @@ client3_getspec_cbk (struct rpc_req *req, struct iovec *iov, int count,
 
         frame = myframe;
 
-        if (-1 == req->rpc_status) {
+        if (!frame || !frame->this) {
+                gf_log ("", GF_LOG_ERROR, "frame not found with the request, "
+                        "returning EINVAL");
                 rsp.op_ret   = -1;
                 rsp.op_errno = EINVAL;
                 goto out;
         }
+        if (-1 == req->rpc_status) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "received RPC status error, returning ENOTCONN");
+                rsp.op_ret   = -1;
+                rsp.op_errno = ENOTCONN;
+                goto out;
+        }
 
         ret = xdr_to_getspec_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (frame->this->name, GF_LOG_ERROR,
+                        "XDR decoding failed, returning EINVAL");
                 rsp.op_ret   = -1;
                 rsp.op_errno = EINVAL;
                 goto out;
         }
 
         if (-1 == rsp.op_ret) {
-                gf_log (frame->this->name, GF_LOG_ERROR,
+                gf_log (frame->this->name, GF_LOG_WARNING,
                         "failed to get the 'volume file' from server");
                 goto out;
         }
@@ -337,6 +366,7 @@ int32_t client3_getspec (call_frame_t *frame, xlator_t *this, void *data)
 
         return 0;
 unwind:
+        gf_log (this->name, GF_LOG_WARNING, "failed to send the request");
         STACK_UNWIND_STRICT (getspec, frame, -1, op_errno, NULL);
         return 0;
 
@@ -380,10 +410,15 @@ client3_1_reopen_cbk (struct rpc_req *req, struct iovec *iov, int count,
         call_frame_t  *frame                 = NULL;
 
         frame = myframe;
+        if (!frame || !frame->this)
+                goto out;
+
         local = frame->local;
         conf  = frame->this->private;
 
         if (-1 == req->rpc_status) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "received RPC status error, returning ENOTCONN");
                 rsp.op_ret   = -1;
                 rsp.op_errno = ENOTCONN;
                 goto out;
@@ -391,18 +426,18 @@ client3_1_reopen_cbk (struct rpc_req *req, struct iovec *iov, int count,
 
         ret = xdr_to_open_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (frame->this->name, GF_LOG_ERROR, "XDR decoding failed");
                 rsp.op_ret   = -1;
                 rsp.op_errno = EINVAL;
                 goto out;
         }
 
         if (rsp.op_ret < 0) {
-                gf_log (frame->this->name, GF_LOG_NORMAL,
+                gf_log (frame->this->name, GF_LOG_WARNING,
                         "reopen on %s failed (%s)",
                         local->loc.path, strerror (rsp.op_errno));
         } else {
-                gf_log (frame->this->name, GF_LOG_NORMAL,
+                gf_log (frame->this->name, GF_LOG_DEBUG,
                         "reopen on %s succeeded (remote-fd = %"PRId64")",
                         local->loc.path, rsp.fd);
         }
@@ -415,6 +450,7 @@ client3_1_reopen_cbk (struct rpc_req *req, struct iovec *iov, int count,
         fdctx = local->fdctx;
 
         if (!fdctx) {
+                gf_log (frame->this->name, GF_LOG_WARNING, "fdctx not found");
                 ret = -1;
                 goto out;
         }
@@ -437,18 +473,18 @@ client3_1_reopen_cbk (struct rpc_req *req, struct iovec *iov, int count,
                 ret = client_attempt_lock_recovery (frame->this, local->fdctx);
                 if (ret < 0) {
                         gf_log (frame->this->name, GF_LOG_DEBUG,
-                                "No locks on fd to recover");
+                                "lock recovery not attempted on fd");
                 } else {
-                        gf_log (frame->this->name, GF_LOG_DEBUG,
-                                "Need to attempt lock recovery on %lld open fds",
-                                (unsigned long long) fd_count);
+                        gf_log (frame->this->name, GF_LOG_INFO,
+                                "need to attempt lock recovery on %"PRIu64
+                                " open fds", fd_count);
                 }
-        } else {
-                fd_count = decrement_reopen_fd_count (frame->this, conf);
         }
 
-
 out:
+        if (!attempt_lock_recovery)
+                fd_count = decrement_reopen_fd_count (frame->this, conf);
+
         if (fdctx)
                 client_fdctx_destroy (frame->this, fdctx);
 
@@ -479,10 +515,11 @@ client3_1_reopendir_cbk (struct rpc_req *req, struct iovec *iov, int count,
                 goto out;
 
         local        = frame->local;
-        frame->local = NULL;
         conf         = frame->this->private;
 
         if (-1 == req->rpc_status) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "received RPC status error, returning ENOTCONN");
                 rsp.op_ret   = -1;
                 rsp.op_errno = ENOTCONN;
                 goto out;
@@ -490,14 +527,14 @@ client3_1_reopendir_cbk (struct rpc_req *req, struct iovec *iov, int count,
 
         ret = xdr_to_opendir_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (frame->this->name, GF_LOG_ERROR, "XDR decoding failed");
                 rsp.op_ret   = -1;
                 rsp.op_errno = EINVAL;
                 goto out;
         }
 
         if (rsp.op_ret < 0) {
-                gf_log (frame->this->name, GF_LOG_NORMAL,
+                gf_log (frame->this->name, GF_LOG_WARNING,
                         "reopendir on %s failed (%s)",
                         local->loc.path, strerror (rsp.op_errno));
         } else {
@@ -506,23 +543,29 @@ client3_1_reopendir_cbk (struct rpc_req *req, struct iovec *iov, int count,
                         local->loc.path, rsp.fd);
         }
 
-	if (-1 != rsp.op_ret) {
-                fdctx = local->fdctx;
-                if (fdctx) {
-                        pthread_mutex_lock (&conf->lock);
-                        {
-                                fdctx->remote_fd = rsp.fd;
+	if (-1 == rsp.op_ret) {
+                ret = -1;
+                goto out;
+        }
 
-                                if (!fdctx->released) {
-                                        list_add_tail (&fdctx->sfd_pos, &conf->saved_fds);
-                                        fdctx = NULL;
-                                }
-                        }
-                        pthread_mutex_unlock (&conf->lock);
+        fdctx = local->fdctx;
+        if (!fdctx) {
+                gf_log (frame->this->name, GF_LOG_WARNING, "fdctx not found");
+                ret = -1;
+                goto out;
+        }
+
+        pthread_mutex_lock (&conf->lock);
+        {
+                fdctx->remote_fd = rsp.fd;
+
+                if (!fdctx->released) {
+                        list_add_tail (&fdctx->sfd_pos, &conf->saved_fds);
+                        fdctx = NULL;
                 }
         }
+        pthread_mutex_unlock (&conf->lock);
 
-        decrement_reopen_fd_count (frame->this, conf);
         ret = 0;
 
 out:
@@ -561,6 +604,9 @@ protocol_client_reopendir (xlator_t *this, clnt_fd_ctx_t *fdctx)
 
         ret = inode_path (inode, NULL, &path);
         if (ret < 0) {
+                gf_log (this->name, GF_LOG_WARNING,
+                        "couldn't build path from inode %s",
+                        uuid_utoa (inode->gfid));
                 goto out;
         }
 
@@ -599,6 +645,8 @@ protocol_client_reopendir (xlator_t *this, clnt_fd_ctx_t *fdctx)
         return ret;
 
 out:
+        gf_log ("", GF_LOG_ERROR, "failed to send the re-opendir request");
+
         if (frame) {
                 frame->local = NULL;
                 STACK_DESTROY (frame->root);
@@ -636,6 +684,9 @@ protocol_client_reopen (xlator_t *this, clnt_fd_ctx_t *fdctx)
 
         ret = inode_path (inode, NULL, &path);
         if (ret < 0) {
+                gf_log (this->name, GF_LOG_WARNING,
+                        "couldn't build path from inode %s",
+                        uuid_utoa (inode->gfid));
                 goto out;
         }
 
@@ -674,6 +725,8 @@ protocol_client_reopen (xlator_t *this, clnt_fd_ctx_t *fdctx)
         return ret;
 
 out:
+        gf_log ("", GF_LOG_ERROR, "failed to send the re-open request");
+
         if (frame) {
                 frame->local = NULL;
                 STACK_DESTROY (frame->root);
@@ -742,9 +795,8 @@ client_post_handshake (call_frame_t *frame, xlator_t *this)
                 }
         } else {
                 gf_log (this->name, GF_LOG_DEBUG,
-                        "No open fds - notifying all parents child up");
+                        "no open fds - notifying all parents child up");
                 client_notify_parents_child_up (this);
-
         }
 out:
         return 0;
@@ -771,13 +823,15 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
         conf  = this->private;
 
         if (-1 == req->rpc_status) {
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "received RPC status error");
                 op_ret = -1;
                 goto out;
         }
 
         ret = xdr_to_setvolume_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (this->name, GF_LOG_ERROR, "XDR decoding failed");
                 op_ret = -1;
                 goto out;
         }
@@ -785,7 +839,8 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
         op_errno = gf_error_to_errno (rsp.op_errno);
         if (-1 == rsp.op_ret) {
                 gf_log (frame->this->name, GF_LOG_WARNING,
-                        "failed to set the volume");
+                        "failed to set the volume (%s)",
+                        (op_errno)? strerror (op_errno) : "--");
         }
 
         reply = dict_new ();
@@ -796,7 +851,7 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
                 ret = dict_unserialize (rsp.dict.dict_val,
                                         rsp.dict.dict_len, &reply);
                 if (ret < 0) {
-                        gf_log (frame->this->name, GF_LOG_DEBUG,
+                        gf_log (frame->this->name, GF_LOG_WARNING,
                                 "failed to unserialize buffer to dict");
                         goto out;
                 }
@@ -804,13 +859,13 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
 
         ret = dict_get_str (reply, "ERROR", &remote_error);
         if (ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "failed to get ERROR string from reply dict");
         }
 
         ret = dict_get_str (reply, "process-uuid", &process_uuid);
         if (ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "failed to get 'process-uuid' from reply dict");
         }
 
@@ -830,10 +885,14 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
                 }
                 goto out;
         }
+
         ret = dict_get_str (this->options, "remote-subvolume",
                             &remote_subvol);
-        if (ret || !remote_subvol)
+        if (ret || !remote_subvol) {
+                gf_log (this->name, GF_LOG_WARNING,
+                        "failed to find key 'remote-subvolume' in the options");
                 goto out;
+        }
 
         /* TODO: currently setpeer path is broken */
         /*
@@ -857,7 +916,7 @@ client_setvolume_cbk (struct rpc_req *req, struct iovec *iov, int count, void *m
         }
         */
 
-        gf_log (this->name, GF_LOG_NORMAL,
+        gf_log (this->name, GF_LOG_INFO,
                 "Connected to %s, attached to remote volume '%s'.",
                 conf->rpc->conn.trans->peerinfo.identifier,
                 remote_subvol);
@@ -878,6 +937,7 @@ out:
                  * background, for now, don't hang here,
                  * tell the parents that i am all ok..
                  */
+                gf_log (this->name, GF_LOG_INFO, "sending CHILD_CONNECTING event");
                 parent = this->parents;
                 while (parent) {
                         xlator_notify (parent->xlator,
@@ -992,6 +1052,7 @@ client_setvolume (xlator_t *this, struct rpc_clnt *rpc)
                                      NULL, 0, NULL);
 
 fail:
+
         if (ret) {
                 config.remote_port = -1;
                 rpc_clnt_reconfig (conf->rpc, &config);
@@ -1010,8 +1071,11 @@ select_server_supported_programs (xlator_t *this, gf_prog_detail *prog)
         clnt_conf_t    *conf     = NULL;
         int             ret      = -1;
 
-        if (!this || !prog)
+        if (!this || !prog) {
+                gf_log ("", GF_LOG_WARNING,
+                        "xlator not found OR RPC program not found");
                 goto out;
+        }
 
         conf = this->private;
         trav = prog;
@@ -1046,8 +1110,11 @@ server_has_portmap (xlator_t *this, gf_prog_detail *prog)
         gf_prog_detail *trav     = NULL;
         int             ret      = -1;
 
-        if (!this || !prog)
+        if (!this || !prog) {
+                gf_log ("", GF_LOG_WARNING,
+                        "xlator not found OR RPC program not found");
                 goto out;
+        }
 
         trav = prog;
 
@@ -1078,26 +1145,29 @@ client_query_portmap_cbk (struct rpc_req *req, struct iovec *iov, int count, voi
         xlator_t                         *this   = NULL;
 
         frame = myframe;
-        if (!frame || !frame->this || !frame->this->private)
+        if (!frame || !frame->this || !frame->this->private) {
+                gf_log ("", GF_LOG_WARNING,
+                        "frame not found with rpc request");
                 goto out;
-
+        }
         this  = frame->this;
         conf  = frame->this->private;
 
         if (-1 == req->rpc_status) {
-                gf_log ("", 1, "some error, retry again later");
+                gf_log (this->name, GF_LOG_WARNING,
+                        "received RPC status error, try again later");
                 goto out;
         }
 
         ret = xdr_to_pmap_port_by_brick_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (this->name, GF_LOG_ERROR, "XDR decoding failed");
                 goto out;
         }
 
         if (-1 == rsp.op_ret) {
                 ret = -1;
-                gf_log (frame->this->name, GF_LOG_ERROR,
+                gf_log (this->name, GF_LOG_ERROR,
                         "failed to get the port number for remote subvolume");
                 goto out;
         }
@@ -1175,17 +1245,18 @@ client_dump_version_cbk (struct rpc_req *req, struct iovec *iov, int count,
         conf  = frame->this->private;
 
         if (-1 == req->rpc_status) {
-                gf_log ("", 1, "some error, retry again later");
+                gf_log (frame->this->name, GF_LOG_WARNING,
+                        "received RPC status error");
                 goto out;
         }
 
         ret = xdr_to_dump_rsp (*iov, &rsp);
         if (ret < 0) {
-                gf_log ("", GF_LOG_ERROR, "error");
+                gf_log (frame->this->name, GF_LOG_ERROR, "XDR decoding failed");
                 goto out;
         }
         if (-1 == rsp.op_ret) {
-                gf_log (frame->this->name, GF_LOG_ERROR,
+                gf_log (frame->this->name, GF_LOG_WARNING,
                         "failed to get the 'versions' from server");
                 goto out;
         }
@@ -1200,8 +1271,7 @@ client_dump_version_cbk (struct rpc_req *req, struct iovec *iov, int count,
         ret = select_server_supported_programs (frame->this, rsp.prog);
         if (ret) {
                 gf_log (frame->this->name, GF_LOG_ERROR,
-                        "Server versions are not present in this "
-                        "release");
+                        "server doesn't support the version");
                 goto out;
         }
 
@@ -1236,8 +1306,10 @@ client_handshake (xlator_t *this, struct rpc_clnt *rpc)
         int           ret   = 0;
 
         conf = this->private;
-        if (!conf->handshake)
+        if (!conf->handshake) {
+                gf_log (this->name, GF_LOG_WARNING, "handshake program not found");
                 goto out;
+        }
 
         frame = create_frame (this, this->ctx->pool);
         if (!frame)