protocol/server: log enhancements

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

5 files changed, 175 insertions, 105 deletions

diff --git a/xlators/protocol/server/src/server-handshake.c b/xlators/protocol/server/src/server-handshake.c
index 1dc05f032b2..66b9ea78d23 100644
--- a/xlators/protocol/server/src/server-handshake.c
+++ b/xlators/protocol/server/src/server-handshake.c
@@ -102,7 +102,7 @@ _volfile_update_checksum (xlator_t *this, char *key, uint32_t checksum)
         }
 
         if (temp_volfile->checksum != checksum) {
-                gf_log (this->name, GF_LOG_CRITICAL,
+                gf_log (this->name, GF_LOG_INFO,
                         "the volume file got modified between earlier access "
                         "and now, this may lead to inconsistency between "
                         "clients, advised to remount client");
@@ -211,7 +211,7 @@ _validate_volfile_checksum (xlator_t *this, char *key,
                 fd = open (filename, O_RDONLY);
                 if (-1 == fd) {
                         ret = 0;
-                        gf_log (this->name, GF_LOG_DEBUG,
+                        gf_log (this->name, GF_LOG_INFO,
                                 "failed to open volume file (%s) : %s",
                                 filename, strerror (errno));
                         goto out;
@@ -372,7 +372,6 @@ server_setvolume (rpcsvc_request_t *req)
 
         buf = memdup (args.dict.dict_val, args.dict.dict_len);
         if (buf == NULL) {
-                gf_log (this->name, GF_LOG_ERROR, "out of memory");
                 op_ret = -1;
                 op_errno = ENOMEM;
                 goto fail;
diff --git a/xlators/protocol/server/src/server-helpers.c b/xlators/protocol/server/src/server-helpers.c
index 78d850fc75d..da3124ff784 100644
--- a/xlators/protocol/server/src/server-helpers.c
+++ b/xlators/protocol/server/src/server-helpers.c
@@ -162,8 +162,6 @@ gf_add_locker (struct _lock_table *table, const char *volume,
 
         new = GF_CALLOC (1, sizeof (struct _locker), gf_server_mt_locker_t);
         if (new == NULL) {
-                gf_log ("server", GF_LOG_ERROR,
-                        "failed to allocate memory for \'struct _locker\'");
                 goto out;
         }
         INIT_LIST_HEAD (&new->lockers);
@@ -259,8 +257,6 @@ gf_lock_table_new (void)
 
         new = GF_CALLOC (1, sizeof (struct _lock_table), gf_server_mt_lock_table_t);
         if (new == NULL) {
-                gf_log ("server-protocol", GF_LOG_CRITICAL,
-                        "failed to allocate memory for new lock table");
                 goto out;
         }
         INIT_LIST_HEAD (&new->entrylk_lockers);
@@ -331,8 +327,6 @@ do_lock_table_cleanup (xlator_t *this, server_connection_t *conn,
                                   tmp, &inodelk_lockers, lockers) {
                 tmp_frame = copy_frame (frame);
                 if (tmp_frame == NULL) {
-                        gf_log (this->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }
                 /*
@@ -483,8 +477,6 @@ do_fd_cleanup (xlator_t *this, server_connection_t *conn, call_frame_t *frame,
                 if (fd != NULL) {
                         tmp_frame = copy_frame (frame);
                         if (tmp_frame == NULL) {
-                                gf_log (this->name, GF_LOG_ERROR,
-                                        "out of memory");
                                 goto out;
                         }
 
@@ -538,7 +530,6 @@ do_connection_cleanup (xlator_t *this, server_connection_t *conn,
 
         frame = create_frame (this, this->ctx->pool);
         if (frame == NULL) {
-                gf_log (this->name, GF_LOG_ERROR, "out of memory");
                 goto out;
         }
 
@@ -896,10 +887,12 @@ server_alloc_frame (rpcsvc_request_t *req)
         GF_VALIDATE_OR_GOTO ("server", conn, out);
 
         frame = create_frame (conn->this, req->svc->ctx->pool);
-        GF_VALIDATE_OR_GOTO ("server", frame, out);
+        if (!frame)
+                goto out;
 
         state = GF_CALLOC (1, sizeof (*state), gf_server_mt_state_t);
-        GF_VALIDATE_OR_GOTO ("server", state, out);
+        if (!state)
+                goto out;
 
         if (conn->bound_xl)
                 state->itable = conn->bound_xl->itable;
@@ -928,7 +921,8 @@ get_frame_from_request (rpcsvc_request_t *req)
         GF_VALIDATE_OR_GOTO ("server", req, out);
 
         frame = server_alloc_frame (req);
-        GF_VALIDATE_OR_GOTO ("server", frame, out);
+        if (!frame)
+                goto out;
 
         frame->root->op       = req->procnum;
         frame->root->type     = req->type;
@@ -1320,7 +1314,9 @@ server_print_request (call_frame_t *frame)
         conf = this->private;
 
         GF_VALIDATE_OR_GOTO ("server", conf, out);
-        GF_VALIDATE_OR_GOTO ("server", conf->trace, out);
+
+        if (!conf->trace)
+                goto out;
 
         state = CALL_STATE (frame);
 
diff --git a/xlators/protocol/server/src/server-resolve.c b/xlators/protocol/server/src/server-resolve.c
index 1da41b2fd59..0b0487a242a 100644
--- a/xlators/protocol/server/src/server-resolve.c
+++ b/xlators/protocol/server/src/server-resolve.c
@@ -70,7 +70,8 @@ prepare_components (call_frame_t *frame)
         count = component_count (resolve->path);
         components = GF_CALLOC (sizeof (*components), count,
                                 gf_server_mt_resolv_comp_t);
-        GF_VALIDATE_OR_GOTO ("server", components, out);
+        if (!components)
+                goto out;
 
         resolve->components = components;
 
@@ -194,6 +195,10 @@ resolve_deep_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         i = (long) cookie;
 
         if (op_ret == -1) {
+                gf_log (this->name, ((op_errno == ENOENT) ? GF_LOG_DEBUG :
+                                     GF_LOG_WARNING),
+                        "%s: failed to resolve (%s)",
+                        resolve->resolved, strerror (op_errno));
                 goto get_out_of_here;
         }
 
@@ -285,6 +290,8 @@ resolve_path_simple (call_frame_t *frame)
         components = resolve->components;
 
         if (!components) {
+                gf_log ("", GF_LOG_INFO,
+                        "failed to resolve, component not found");
                 resolve->op_ret   = -1;
                 resolve->op_errno = ENOENT;
                 goto out;
@@ -296,6 +303,8 @@ resolve_path_simple (call_frame_t *frame)
         }
 
         if (ino_idx == -1) {
+                gf_log ("", GF_LOG_INFO,
+                        "failed to resolve, inode index not found");
                 resolve->op_ret  = -1;
                 resolve->op_errno = EINVAL;
                 goto out;
@@ -306,6 +315,8 @@ resolve_path_simple (call_frame_t *frame)
                 goto noparent;
 
         if (!components[par_idx].inode) {
+                gf_log ("", GF_LOG_INFO,
+                        "failed to resolve, parent inode not found");
                 resolve->op_ret    = -1;
                 resolve->op_errno  = ENOENT;
                 goto out;
@@ -315,12 +326,16 @@ noparent:
 
         if (!components[ino_idx].inode &&
             (resolve->type == RESOLVE_MUST || resolve->type == RESOLVE_EXACT)) {
+                gf_log ("", GF_LOG_INFO,
+                        "failed to resolve, inode not found");
                 resolve->op_ret    = -1;
                 resolve->op_errno  = ENOENT;
                 goto out;
         }
 
         if (components[ino_idx].inode && resolve->type == RESOLVE_NOT) {
+                gf_log ("", GF_LOG_INFO,
+                        "failed to resolve, inode found");
                 resolve->op_ret    = -1;
                 resolve->op_errno  = EEXIST;
                 goto out;
@@ -399,7 +414,7 @@ resolve_entry_simple (call_frame_t *frame)
         }
 
         if (resolve->type == RESOLVE_NOT) {
-                gf_log (this->name, GF_LOG_DEBUG, "inode (pointer: %p ino:%"
+                gf_log (this->name, GF_LOG_INFO, "inode (pointer: %p ino:%"
                         PRIu64") found for path (%s) while type is RESOLVE_NOT",
                         inode, inode->ino, resolve->path);
                 resolve->op_ret   = -1;
@@ -526,6 +541,7 @@ server_resolve_fd (call_frame_t *frame)
         state->fd = gf_fd_fdptr_get (conn->fdtable, fd_no);
 
         if (!state->fd) {
+                gf_log ("", GF_LOG_INFO, "fd not found in context");
                 resolve->op_ret   = -1;
                 resolve->op_errno = EBADF;
         }
@@ -559,7 +575,7 @@ server_resolve (call_frame_t *frame)
 
         } else if (resolve->path) {
 
-                gf_log (frame->this->name, GF_LOG_WARNING,
+                gf_log (frame->this->name, GF_LOG_INFO,
                         "pure path resolution for %s (%s)",
                         resolve->path, gf_fop_list[frame->root->op]);
                 resolve_path_deep (frame);
diff --git a/xlators/protocol/server/src/server.c b/xlators/protocol/server/src/server.c
index 5b2560f5828..c1bcf61e431 100644
--- a/xlators/protocol/server/src/server.c
+++ b/xlators/protocol/server/src/server.c
@@ -50,7 +50,7 @@ gfs_serialize_reply (rpcsvc_request_t *req, void *arg, gfs_serialize_t sfunc,
          */
         iob = iobuf_get (req->svc->ctx->iobuf_pool);
         if (!iob) {
-                gf_log ("", GF_LOG_ERROR, "Failed to get iobuf");
+                gf_log_callingfn ("", GF_LOG_ERROR, "Failed to get iobuf");
                 goto ret;
         }
 
@@ -66,7 +66,7 @@ gfs_serialize_reply (rpcsvc_request_t *req, void *arg, gfs_serialize_t sfunc,
                 /* Failed to Encode 'GlusterFS' msg in RPC is not exactly
                    failure of RPC return values.. client should get
                    notified about this, so there are no missing frames */
-                gf_log ("", GF_LOG_ERROR, "Failed to encode message");
+                gf_log_callingfn ("", GF_LOG_ERROR, "Failed to encode message");
                 req->rpc_err = GARBAGE_ARGS;
                 retlen = 0;
         }
@@ -105,7 +105,6 @@ server_submit_reply (call_frame_t *frame, rpcsvc_request_t *req, void *arg,
         if (!iobref) {
                 iobref = iobref_new ();
                 if (!iobref) {
-                        gf_log ("", GF_LOG_ERROR, "out of memory");
                         goto ret;
                 }
 
@@ -134,7 +133,7 @@ server_submit_reply (call_frame_t *frame, rpcsvc_request_t *req, void *arg,
          */
         iobuf_unref (iob);
         if (ret == -1) {
-                gf_log ("", GF_LOG_ERROR, "Reply submission failed");
+                gf_log_callingfn ("", GF_LOG_ERROR, "Reply submission failed");
                 goto ret;
         }
 
@@ -403,8 +402,8 @@ server_rpc_notify (rpcsvc_t *rpc, void *xl, rpcsvc_event_t event,
 
 
         if (!xl || !data) {
-                gf_log ("server", GF_LOG_WARNING,
-                        "Calling rpc_notify without initializing");
+                gf_log_callingfn ("server", GF_LOG_WARNING,
+                                  "Calling rpc_notify without initializing");
                 goto out;
         }
 
@@ -482,12 +481,10 @@ validate_options (xlator_t *this, dict_t *options, char **op_errstr)
         data_t           *data;
         gf_boolean_t      trace;
 
-
-
         if (dict_get_int32 ( options, "inode-lru-limit", &inode_lru_limit) == 0){
                 if (!(inode_lru_limit < (1 * GF_UNIT_MB)  &&
                       inode_lru_limit >1 )) {
-                        gf_log (this->name, GF_LOG_DEBUG, "Validate inode-lru"
+                        gf_log (this->name, GF_LOG_INFO, "Validate inode-lru"
                                 "-limit %d, was WRONG", inode_lru_limit);
                         snprintf (errstr,1024, "Error, Greater than max value %d "
                                   ,inode_lru_limit);
@@ -515,7 +512,6 @@ validate_options (xlator_t *this, dict_t *options, char **op_errstr)
 
         auth_modules = dict_new ();
         if (!auth_modules) {
-                gf_log (this->name, GF_LOG_ERROR, "Out of memory");
                 ret = -1;
                 goto out;
         }
@@ -587,7 +583,7 @@ reconfigure (xlator_t *this, dict_t *options)
         conf = this->private;
 
         if (!conf) {
-                gf_log (this->name, GF_LOG_DEBUG, "conf == null!!!");
+                gf_log_callingfn (this->name, GF_LOG_DEBUG, "conf == null!!!");
                 goto out;
         }
         if (dict_get_int32 ( options, "inode-lru-limit", &inode_lru_limit) == 0){
@@ -709,6 +705,8 @@ init (xlator_t *this)
         //conf->rpc = rpc_svc_init (&conf->rpc_conf);
         conf->rpc = rpcsvc_init (this->ctx, this->options);
         if (conf->rpc == NULL) {
+                gf_log (this->name, GF_LOG_WARNING,
+                        "creation of rpcsvc failed");
                 ret = -1;
                 goto out;
         }
@@ -716,7 +714,7 @@ init (xlator_t *this)
         ret = rpcsvc_create_listeners (conf->rpc, this->options,
                                        this->name);
         if (ret < 1) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "creation of listener failed");
                 ret = -1;
                 goto out;
@@ -724,7 +722,7 @@ init (xlator_t *this)
 
         ret = rpcsvc_register_notify (conf->rpc, server_rpc_notify, this);
         if (ret) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "registration of notify with rpcsvc failed");
                 goto out;
         }
@@ -732,7 +730,7 @@ init (xlator_t *this)
         glusterfs3_1_fop_prog.options = this->options;
         ret = rpcsvc_program_register (conf->rpc, &glusterfs3_1_fop_prog);
         if (ret) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "registration of program (name:%s, prognum:%d, "
                         "progver:%d) failed", glusterfs3_1_fop_prog.progname,
                         glusterfs3_1_fop_prog.prognum,
@@ -743,7 +741,7 @@ init (xlator_t *this)
         gluster_handshake_prog.options = this->options;
         ret = rpcsvc_program_register (conf->rpc, &gluster_handshake_prog);
         if (ret) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_WARNING,
                         "registration of program (name:%s, prognum:%d, "
                         "progver:%d) failed", gluster_handshake_prog.progname,
                         gluster_handshake_prog.prognum,
diff --git a/xlators/protocol/server/src/server3_1-fops.c b/xlators/protocol/server/src/server3_1-fops.c
index 43f7c82d428..2d1e9d0391a 100644
--- a/xlators/protocol/server/src/server3_1-fops.c
+++ b/xlators/protocol/server/src/server3_1-fops.c
@@ -47,6 +47,10 @@ server_statfs_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
         if (op_ret >= 0) {
                 gf_statfs_from_statfs (&rsp.statfs, buf);
+        } else {
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": STATFS %"PRId32" (%s)",
+                        frame->root->unique, op_ret, strerror (op_errno));
         }
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
@@ -66,9 +70,9 @@ server_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         inode_t          *root_inode = NULL;
         inode_t          *link_inode = NULL;
         loc_t             fresh_loc  = {0,};
-        gfs3_lookup_rsp   rsp        = {0, };
+        gfs3_lookup_rsp   rsp        = {0,};
         int32_t           ret        = -1;
-        uuid_t            rootgfid   = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1};
+        uuid_t            rootgfid   = {0,};
 
         state = CALL_STATE(frame);
 
@@ -128,6 +132,7 @@ server_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 if (inode == root_inode) {
                         /* we just looked up root ("/") */
                         stbuf->ia_ino = 1;
+                        rootgfid[15]  = 1;
                         uuid_copy (stbuf->ia_gfid, rootgfid);
                         if (inode->ia_type == 0)
                                 inode->ia_type = stbuf->ia_type;
@@ -149,17 +154,19 @@ server_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                               state->loc.name);
                         }
                 }
+        }
+out:
+        rsp.op_ret   = op_ret;
+        rsp.op_errno = gf_errno_to_error (op_errno);
 
+        if (op_ret) {
                 gf_log (this->name,
-                        (op_errno == ENOENT ? GF_LOG_TRACE : GF_LOG_DEBUG),
+                        (op_errno == ENOENT ? GF_LOG_TRACE : GF_LOG_INFO),
                         "%"PRId64": LOOKUP %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
                         op_ret, strerror (op_errno));
         }
-out:
-        rsp.op_ret   = op_ret;
-        rsp.op_errno = gf_errno_to_error (op_errno);
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              (gfs_serialize_t)xdr_serialize_lookup_rsp);
@@ -205,7 +212,7 @@ server_lk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
                 gf_proto_flock_from_flock (&rsp.flock, lock);
         } else if (op_errno != ENOSYS) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": LK %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -245,7 +252,7 @@ server_inodelk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                        &state->loc, NULL, frame->root->pid,
                                        frame->root->lk_owner, GF_FOP_INODELK);
         } else if (op_errno != ENOSYS) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": INODELK %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0, op_ret,
@@ -287,7 +294,7 @@ server_finodelk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                        frame->root->pid,
                                        frame->root->lk_owner, GF_FOP_INODELK);
         } else if (op_errno != ENOSYS) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FINODELK %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -326,7 +333,7 @@ server_entrylk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                        &state->loc, NULL, frame->root->pid,
                                        frame->root->lk_owner, GF_FOP_ENTRYLK);
         } else if (op_errno != ENOSYS) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": INODELK %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0, op_ret,
@@ -364,7 +371,7 @@ server_fentrylk_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                        NULL, state->fd, frame->root->pid,
                                        frame->root->lk_owner, GF_FOP_ENTRYLK);
         } else if (op_errno != ENOSYS) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FENTRYLK %"PRId64" (%"PRId64") "
                         " ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
@@ -385,11 +392,20 @@ server_access_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 {
         gf_common_rsp     rsp = {0,};
         rpcsvc_request_t *req = NULL;
+        server_state_t   *state = NULL;
 
         req           = frame->local;
 
+        state = CALL_STATE(frame);
+
         rsp.op_ret    = op_ret;
         rsp.op_errno  = gf_errno_to_error (op_errno);
+        if (op_ret)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": ACCESS %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_common_rsp);
@@ -426,7 +442,7 @@ server_rmdir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.preparent, preparent);
                 gf_stat_from_iatt (&rsp.postparent, postparent);
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": RMDIR %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -466,7 +482,7 @@ server_mkdir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 inode_lookup (link_inode);
                 inode_unref (link_inode);
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": MKDIR %s  ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         op_ret, strerror (op_errno));
@@ -505,7 +521,7 @@ server_mknod_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 inode_lookup (link_inode);
                 inode_unref (link_inode);
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": MKNOD %s ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         op_ret, strerror (op_errno));
@@ -534,7 +550,7 @@ server_fsyncdir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         state = CALL_STATE(frame);
 
         if (op_ret < 0) {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FSYNCDIR %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -567,7 +583,7 @@ server_readdir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                         goto unwind;
                 }
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": READDIR %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -623,7 +639,7 @@ server_opendir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 fd_no = gf_fd_unused_get (conn->fdtable, fd);
                 fd_ref (fd); // on behalf of the client
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": OPENDIR %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -648,11 +664,19 @@ server_removexattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 {
         gf_common_rsp     rsp = {0,};
         rpcsvc_request_t *req = NULL;
+        server_state_t      *state = NULL;
 
-        req           = frame->local;
+        req   = frame->local;
+        state = CALL_STATE(frame);
 
         rsp.op_ret    = op_ret;
         rsp.op_errno  = gf_errno_to_error (op_errno);
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": REMOVEXATTR %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_common_rsp);
@@ -709,6 +733,12 @@ out:
         rsp.op_ret        = op_ret;
         rsp.op_errno      = gf_errno_to_error (op_errno);
         rsp.dict.dict_len = len;
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": GETXATTR %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_getxattr_rsp);
@@ -768,6 +798,13 @@ out:
         rsp.op_ret        = op_ret;
         rsp.op_errno      = gf_errno_to_error (op_errno);
         rsp.dict.dict_len = len;
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": FGETXATTR %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->resolve.fd_no,
+                        state->fd ? state->fd->inode->ino : 0, op_ret,
+                        strerror (op_errno));
+
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_fgetxattr_rsp);
 
@@ -783,12 +820,20 @@ server_setxattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 {
         gf_common_rsp     rsp = {0,};
         rpcsvc_request_t *req = NULL;
+        server_state_t      *state = NULL;
 
         req           = frame->local;
 
+        state = CALL_STATE(frame);
         rsp.op_ret    = op_ret;
         rsp.op_errno  = gf_errno_to_error (op_errno);
 
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": SETXATTR %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_common_rsp);
 
@@ -802,12 +847,21 @@ server_fsetxattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 {
         gf_common_rsp     rsp = {0,};
         rpcsvc_request_t *req = NULL;
+        server_state_t      *state = NULL;
 
         req           = frame->local;
 
+        state = CALL_STATE(frame);
         rsp.op_ret    = op_ret;
         rsp.op_errno  = gf_errno_to_error (op_errno);
 
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": FSETXATTR %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->resolve.fd_no,
+                        state->fd ? state->fd->inode->ino : 0, op_ret,
+                        strerror (op_errno));
+
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_common_rsp);
 
@@ -855,6 +909,13 @@ server_rename_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.postnewparent, postnewparent);
         }
 
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": RENAME %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
+
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_rename_rsp);
 
@@ -897,7 +958,7 @@ server_unlink_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.postparent, postparent);
 
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": UNLINK %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -937,7 +998,7 @@ server_symlink_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 inode_lookup (link_inode);
                 inode_unref (link_inode);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": SYMLINK %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -982,6 +1043,13 @@ server_link_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 inode_unref (link_inode);
         }
 
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": LINK %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
+
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_link_rsp);
 
@@ -1008,7 +1076,7 @@ server_truncate_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.prestat, prebuf);
                 gf_stat_from_iatt (&rsp.poststat, postbuf);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": TRUNCATE %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1039,7 +1107,7 @@ server_fstat_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret == 0) {
                 gf_stat_from_iatt (&rsp.stat, stbuf);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FSTAT %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -1072,7 +1140,7 @@ server_ftruncate_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.prestat, prebuf);
                 gf_stat_from_iatt (&rsp.poststat, postbuf);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FTRUNCATE %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -1100,7 +1168,7 @@ server_flush_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
         state = CALL_STATE(frame);
         if (op_ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FLUSH %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -1130,15 +1198,15 @@ server_fsync_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
         state = CALL_STATE(frame);
 
-        if (op_ret < 0) {
-                gf_log (this->name, GF_LOG_DEBUG,
+        if (op_ret >= 0) {
+                gf_stat_from_iatt (&(rsp.prestat), prebuf);
+                gf_stat_from_iatt (&(rsp.poststat), postbuf);
+        } else {
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FSYNC %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
                         strerror (op_errno));
-        } else {
-                gf_stat_from_iatt (&(rsp.prestat), prebuf);
-                gf_stat_from_iatt (&(rsp.poststat), postbuf);
         }
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
@@ -1148,24 +1216,6 @@ server_fsync_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 }
 
 int
-server_release_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
-                    int32_t op_ret, int32_t op_errno)
-{
-        gf_common_rsp     rsp = {0,};
-        rpcsvc_request_t *req = NULL;
-
-        req           = frame->local;
-
-        rsp.op_ret    = op_ret;
-        rsp.op_errno  = gf_errno_to_error (op_errno);
-
-        server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
-                             xdr_serialize_common_rsp);
-        return 0;
-}
-
-
-int
 server_writev_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                    int32_t op_ret, int32_t op_errno, struct iatt *prebuf,
                    struct iatt *postbuf)
@@ -1184,7 +1234,7 @@ server_writev_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.prestat, prebuf);
                 gf_stat_from_iatt (&rsp.poststat, postbuf);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": WRITEV %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -1218,7 +1268,7 @@ server_readv_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.stat, stbuf);
                 rsp.size = op_ret;
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": READV %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
                         state->fd ? state->fd->inode->ino : 0, op_ret,
@@ -1238,9 +1288,11 @@ server_rchecksum_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 {
         gfs3_rchecksum_rsp  rsp = {0,};
         rpcsvc_request_t   *req = NULL;
+        server_state_t      *state = NULL;
 
         req           = frame->local;
 
+        state = CALL_STATE(frame);
         rsp.op_ret    = op_ret;
         rsp.op_errno  = gf_errno_to_error (op_errno);
 
@@ -1250,6 +1302,12 @@ server_rchecksum_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 rsp.strong_checksum.strong_checksum_val = (char *)strong_checksum;
                 rsp.strong_checksum.strong_checksum_len = MD5_DIGEST_LEN;
         }
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": RCHECKSUM %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->resolve.fd_no,
+                        state->fd ? state->fd->inode->ino : 0, op_ret,
+                        strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_rchecksum_rsp);
@@ -1276,7 +1334,7 @@ server_open_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 fd_no = gf_fd_unused_get (conn->fdtable, fd);
                 fd_ref (fd);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": OPEN %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1353,7 +1411,7 @@ server_create_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.preparent, preparent);
                 gf_stat_from_iatt (&rsp.postparent, postparent);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": CREATE %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1394,7 +1452,7 @@ server_readlink_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.buf, stbuf);
                 rsp.path = (char *)buf;
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": READLINK %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1428,7 +1486,7 @@ server_stat_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (op_ret == 0) {
                 gf_stat_from_iatt (&rsp.stat, stbuf);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": STAT %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1462,7 +1520,7 @@ server_setattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.statpre, statpre);
                 gf_stat_from_iatt (&rsp.statpost, statpost);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": SETATTR %s (%"PRId64") ==> %"PRId32" (%s)",
                         frame->root->unique, state->loc.path,
                         state->loc.inode ? state->loc.inode->ino : 0,
@@ -1490,7 +1548,7 @@ server_fsetattr_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 gf_stat_from_iatt (&rsp.statpre, statpre);
                 gf_stat_from_iatt (&rsp.statpost, statpost);
         } else {
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "%"PRId64": FSETATTR %"PRId64" (%"PRId64") ==> "
                         "%"PRId32" (%s)",
                         frame->root->unique, state->resolve.fd_no,
@@ -1566,6 +1624,12 @@ out:
         rsp.op_ret        = op_ret;
         rsp.op_errno      = gf_errno_to_error (op_errno);
         rsp.dict.dict_len = len;
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": XATTROP %s (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->loc.path,
+                        state->loc.inode ? state->loc.inode->ino : 0,
+                        op_ret, strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_xattrop_rsp);
@@ -1634,6 +1698,12 @@ out:
         rsp.op_ret        = op_ret;
         rsp.op_errno      = gf_errno_to_error (op_errno);
         rsp.dict.dict_len = len;
+        if (op_ret == -1)
+                gf_log (this->name, GF_LOG_INFO,
+                        "%"PRId64": FXATTROP %"PRId64" (%"PRId64") ==> %"PRId32" (%s)",
+                        frame->root->unique, state->resolve.fd_no,
+                        state->fd ? state->fd->inode->ino : 0, op_ret,
+                        strerror (op_errno));
 
         server_submit_reply (frame, req, &rsp, NULL, 0, NULL,
                              xdr_serialize_fxattrop_rsp);
@@ -1665,12 +1735,13 @@ server_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                         goto out;
                 }
         } else {
-                gf_log (this->name, GF_LOG_TRACE,
-                        "%"PRId64": READDIRP %"PRId64" (%"PRId64") ==>"
-                        "%"PRId32" (%s)",
-                        frame->root->unique, state->resolve.fd_no,
-                        state->fd ? state->fd->inode->ino : 0, op_ret,
-                        strerror (op_errno));
+                if (op_errno != ENOENT)
+                        gf_log (this->name, GF_LOG_INFO,
+                                "%"PRId64": READDIRP %"PRId64" (%"PRId64") ==>"
+                                "%"PRId32" (%s)",
+                                frame->root->unique, state->resolve.fd_no,
+                                state->fd ? state->fd->inode->ino : 0, op_ret,
+                                strerror (op_errno));
         }
 
 out:
@@ -2828,8 +2899,6 @@ server_create (rpcsvc_request_t *req)
 
                 buf = memdup (args.dict.dict_val, args.dict.dict_len);
                 if (buf == NULL) {
-                        gf_log (state->conn->bound_xl->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }
 
@@ -4078,8 +4147,6 @@ server_mknod (rpcsvc_request_t *req)
 
                 buf = memdup (args.dict.dict_val, args.dict.dict_len);
                 if (buf == NULL) {
-                        gf_log (state->conn->bound_xl->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }
 
@@ -4178,8 +4245,6 @@ server_mkdir (rpcsvc_request_t *req)
 
                 buf = memdup (args.dict.dict_val, args.dict.dict_len);
                 if (buf == NULL) {
-                        gf_log (state->conn->bound_xl->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }
 
@@ -4626,8 +4691,6 @@ server_symlink (rpcsvc_request_t *req)
 
                 buf = memdup (args.dict.dict_val, args.dict.dict_len);
                 if (buf == NULL) {
-                        gf_log (state->conn->bound_xl->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }
 
@@ -4994,8 +5057,6 @@ server_lookup (rpcsvc_request_t *req)
 
                 buf = memdup (args.dict.dict_val, args.dict.dict_len);
                 if (buf == NULL) {
-                        gf_log (conn->bound_xl->name, GF_LOG_ERROR,
-                                "out of memory");
                         goto out;
                 }