From 6c949d9d0ddc3397eac3207c0718743d49bd8707 Mon Sep 17 00:00:00 2001 From: Anand Avati Date: Sun, 29 Nov 2009 07:45:20 +0000 Subject: protocol/server: enhance trace logging add logging of fop name, callid number and make logging more friendly Signed-off-by: Anand V. Avati Signed-off-by: Anand V. Avati BUG: 315 (generation number support) URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=315 --- xlators/protocol/server/src/server-helpers.h | 2 +- xlators/protocol/server/src/server-protocol.c | 280 +++++++++++++++++++------- xlators/protocol/server/src/server-resolve.c | 9 +- 3 files changed, 206 insertions(+), 85 deletions(-) (limited to 'xlators/protocol/server/src') diff --git a/xlators/protocol/server/src/server-helpers.h b/xlators/protocol/server/src/server-helpers.h index de5b84de840..867035d3334 100644 --- a/xlators/protocol/server/src/server-helpers.h +++ b/xlators/protocol/server/src/server-helpers.h @@ -67,6 +67,6 @@ int32_t gf_direntry_to_bin (dir_entry_t *head, char *bufferp); void -print_server_state (call_frame_t *frame, server_state_t *state, xlator_t *this, int request); +server_print_request (call_frame_t *frame); #endif /* __SERVER_HELPERS_H__ */ diff --git a/xlators/protocol/server/src/server-protocol.c b/xlators/protocol/server/src/server-protocol.c index 9fc9adf14c7..b7b64476518 100644 --- a/xlators/protocol/server/src/server-protocol.c +++ b/xlators/protocol/server/src/server-protocol.c @@ -43,8 +43,28 @@ #include "statedump.h" #include "md5.h" + void -print_resolve_vars (char *str, int size, server_resolve_t *resolve) +print_caller (char *str, int size, call_frame_t *frame) +{ + int filled = 0; + server_state_t *state = NULL; + transport_t *trans = NULL; + + state = CALL_STATE (frame); + trans = state->trans; + + filled += snprintf (str + filled, size - filled, + " Callid=%"PRId64", Client=%s", + frame->root->unique, + trans->peerinfo.identifier); + + return; +} + + +void +server_print_resolve (char *str, int size, server_resolve_t *resolve) { int filled = 0; @@ -53,29 +73,33 @@ print_resolve_vars (char *str, int size, server_resolve_t *resolve) return; } - if (resolve->fd_no) - filled += snprintf (str + filled, size - filled, "fd_no: %"PRId64" ", resolve->fd_no); + filled += snprintf (str + filled, size - filled, + " Resolve={"); + if (resolve->fd_no != -1) + filled += snprintf (str + filled, size - filled, + "fd=%"PRId64",", (uint64_t) resolve->fd_no); if (resolve->ino) - filled += snprintf (str + filled, size - filled, "ino: %llu ", - (unsigned long long) resolve->ino); - if (resolve->gen) - filled += snprintf (str + filled, size - filled, "gen: %"PRIu64" ", resolve->gen); + filled += snprintf (str + filled, size - filled, + "ino=%"PRIu64",", (uint64_t) resolve->ino); if (resolve->par) - filled += snprintf (str + filled, size - filled, "par: %llu ", - (unsigned long long) resolve->par); - if (resolve->path) - filled += snprintf (str + filled, size - filled, "path: %s ", resolve->path); + filled += snprintf (str + filled, size - filled, + "par=%"PRIu64",", (uint64_t) resolve->par); + if (resolve->gen) + filled += snprintf (str + filled, size - filled, + "gen=%"PRIu64",", (uint64_t) resolve->gen); if (resolve->bname) - filled += snprintf (str + filled, size - filled, "bname: %s ", resolve->bname); - if (resolve->resolved) - filled += snprintf (str + filled, size - filled, "resolved: %s ", resolve->resolved); - if (resolve->comp_count) - filled += snprintf (str + filled, size - filled, "comp_count: %d ", resolve->comp_count); + filled += snprintf (str + filled, size - filled, + "bname=%s,", resolve->bname); + if (resolve->path) + filled += snprintf (str + filled, size - filled, + "path=%s", resolve->path); + filled += snprintf (str + filled, size - filled, "}"); } + void -print_loc_vars (char *str, int size, loc_t *loc) +server_print_loc (char *str, int size, loc_t *loc) { int filled = 0; @@ -84,103 +108,204 @@ print_loc_vars (char *str, int size, loc_t *loc) return; } - if (loc->path) - filled += snprintf (str + filled, size - filled, "path: %s ", loc->path); - if (loc->name) - snprintf (str + filled, size - filled, "name: %s ", loc->name); - if (loc->ino) - snprintf (str + filled, size - filled, "ino: %llu ", - (unsigned long long) loc->ino); + filled += snprintf (str + filled, size - filled, + " Loc={"); + if (loc->path) + filled += snprintf (str + filled, size - filled, + "path=%s,", loc->path); + if (loc->inode) + filled += snprintf (str + filled, size - filled, + "inode=%p,", loc->inode); + if (loc->parent) + filled += snprintf (str + filled, size - filled, + "parent=%p", loc->parent); + filled += snprintf (str + filled, size - filled, "}"); } + void -print_state_vars (char *str, int size, server_state_t *state) +server_print_params (char *str, int size, server_state_t *state) { int filled = 0; - if (state->trans) - filled = snprintf (str + filled, size - filled, "transport: %p ", state->trans); - if (state->bound_xl) - filled += snprintf (str + filled, size - filled, "xlator: %s ",state->bound_xl->name); + filled += snprintf (str + filled, size - filled, + " Params={"); + + if (state->fd) + filled += snprintf (str + filled, size - filled, + "fd=%p,", state->fd); if (state->valid) - filled += snprintf (str + filled, size - filled, "valid: %d ", state->valid); + filled += snprintf (str + filled, size - filled, + "valid=%d,", state->valid); if (state->flags) - filled += snprintf (str + filled, size - filled, "flags: %d ", state->flags); + filled += snprintf (str + filled, size - filled, + "flags=%d,", state->flags); if (state->wbflags) - filled += snprintf (str + filled, size - filled, "wbflags: %d ", state->wbflags); + filled += snprintf (str + filled, size - filled, + "wbflags=%d,", state->wbflags); if (state->size) - filled += snprintf (str + filled, size - filled, "size: %Zu ", state->size); + filled += snprintf (str + filled, size - filled, + "size=%Zu,", state->size); if (state->offset) - filled += snprintf (str + filled, size - filled, "offset: %llu ", - (unsigned long long) state->offset); + filled += snprintf (str + filled, size - filled, + "offset=%"PRId64",", state->offset); if (state->cmd) - filled += snprintf (str + filled, size - filled, "cmd: %d ", state->cmd); + filled += snprintf (str + filled, size - filled, + "cmd=%d,", state->cmd); if (state->type) - filled += snprintf (str + filled, size - filled, "type: %d ", state->type); + filled += snprintf (str + filled, size - filled, + "type=%d,", state->type); if (state->name) - filled += snprintf (str + filled, size - filled, "name: %s ", state->name); + filled += snprintf (str + filled, size - filled, + "name=%s,", state->name); if (state->mask) - filled += snprintf (str + filled, size - filled, "mask: %d ", state->mask); + filled += snprintf (str + filled, size - filled, + "mask=%d,", state->mask); if (state->volume) - filled += snprintf (str + filled, size - filled, "volume: %s ", state->volume); + filled += snprintf (str + filled, size - filled, + "volume=%s,", state->volume); + filled += snprintf (str + filled, size - filled, + "bound_xl=%s}", state->bound_xl->name); } -void -print_server_state (call_frame_t *frame, server_state_t *state, xlator_t *this, int request) + +int +server_resolve_is_empty (server_resolve_t *resolve) { - server_conf_t *conf = NULL; - char resolve_vars[256]; - char resolve2_vars[256]; - char loc_vars[256]; - char loc2_vars[256]; - char other_vars[512]; + if (resolve->fd_no != -1) + return 0; - memset (resolve_vars, '\0', 256); - memset (resolve2_vars, '\0', 256); - memset (loc_vars, '\0', 256); - memset (loc2_vars, '\0', 256); - memset (other_vars, '\0', 512); + if (resolve->ino != 0) + return 0; + + if (resolve->gen != 0) + return 0; + + if (resolve->par != 0) + return 0; + + if (resolve->path != 0) + return 0; + + if (resolve->bname != 0) + return 0; + + return 1; +} + + +void +server_print_reply (call_frame_t *frame, int op_ret, int op_errno) +{ + server_conf_t *conf = NULL; + server_state_t *state = NULL; + xlator_t *this = NULL; + char caller[512]; + char fdstr[32]; + char *op = "UNKNOWN"; + this = frame->this; conf = this->private; + if (!conf->trace) return; - if (request) { + state = CALL_STATE (frame); - print_resolve_vars (resolve_vars, 256, &state->resolve); - print_resolve_vars (resolve2_vars, 256, &state->resolve2); + print_caller (caller, 256, frame); - print_loc_vars (loc_vars, 256, &state->loc); - print_loc_vars (loc2_vars, 256, &state->loc2); + switch (frame->root->type) { + case GF_OP_TYPE_FOP_REQUEST: + case GF_OP_TYPE_FOP_REPLY: + op = gf_fop_list[frame->root->op]; + break; + case GF_OP_TYPE_MOP_REQUEST: + case GF_OP_TYPE_MOP_REPLY: + op = gf_mop_list[frame->root->op]; + break; + case GF_OP_TYPE_CBK_REQUEST: + case GF_OP_TYPE_CBK_REPLY: + op = gf_cbk_list[frame->root->op]; + break; + } - print_state_vars (other_vars, 512, state); + fdstr[0] = '\0'; + if (state->fd) + snprintf (fdstr, 128, " fd=%p", state->fd); - gf_log (this->name, GF_LOG_NORMAL, - "[REQUEST] resolve = {%s} resolve2 = {%s} loc = {%s}" - " loc2 = {%s} State Vars = {%s}", - strlen (resolve_vars) ? resolve_vars : "", - strlen (resolve2_vars) ? resolve2_vars : "", - strlen (loc_vars) ? loc_vars : "", - strlen (loc2_vars) ? loc2_vars : "", - strlen (other_vars) ? other_vars : "" - ); - } else { + gf_log (this->name, GF_LOG_NORMAL, + "%s%s => (%d, %d)%s", + op, caller, op_ret, op_errno, fdstr); +} + + +void +server_print_request (call_frame_t *frame) +{ + server_conf_t *conf = NULL; + xlator_t *this = NULL; + server_state_t *state = NULL; + char resolve_vars[256]; + char resolve2_vars[256]; + char loc_vars[256]; + char loc2_vars[256]; + char other_vars[512]; + char caller[512]; + char *op = "UNKNOWN"; + + this = frame->this; + conf = this->private; + + state = CALL_STATE (frame); + + if (!conf->trace) + return; - print_loc_vars (loc_vars, 256, &state->loc); - print_state_vars (other_vars, 512, state); + memset (resolve_vars, '\0', 256); + memset (resolve2_vars, '\0', 256); + memset (loc_vars, '\0', 256); + memset (loc2_vars, '\0', 256); + memset (other_vars, '\0', 256); + + print_caller (caller, 256, frame); + + if (!server_resolve_is_empty (&state->resolve)) { + server_print_resolve (resolve_vars, 256, &state->resolve); + server_print_loc (loc_vars, 256, &state->loc); + } - gf_log (this->name, GF_LOG_NORMAL, - "[REPLY] loc = {%s} State Vars = {%s}", - strlen (loc_vars) ? loc_vars : "", - strlen (other_vars) ? other_vars : "" - ); + if (!server_resolve_is_empty (&state->resolve2)) { + server_print_resolve (resolve2_vars, 256, &state->resolve2); + server_print_loc (loc2_vars, 256, &state->loc2); } + server_print_params (other_vars, 512, state); + + switch (frame->root->type) { + case GF_OP_TYPE_FOP_REQUEST: + case GF_OP_TYPE_FOP_REPLY: + op = gf_fop_list[frame->root->op]; + break; + case GF_OP_TYPE_MOP_REQUEST: + case GF_OP_TYPE_MOP_REPLY: + op = gf_mop_list[frame->root->op]; + break; + case GF_OP_TYPE_CBK_REQUEST: + case GF_OP_TYPE_CBK_REPLY: + op = gf_cbk_list[frame->root->op]; + break; + } + + gf_log (this->name, GF_LOG_NORMAL, + "%s%s%s%s%s%s%s", + gf_fop_list[frame->root->op], caller, + resolve_vars, loc_vars, resolve2_vars, loc2_vars, other_vars); } + static void protocol_server_reply (call_frame_t *frame, int type, int op, gf_hdr_common_t *hdr, size_t hdrlen, @@ -203,7 +328,8 @@ protocol_server_reply (call_frame_t *frame, int type, int op, hdr->type = hton32 (type); hdr->op = hton32 (op); - print_server_state (frame, state, this, 0); + server_print_reply (frame, ntoh32 (hdr->rsp.op_ret), + gf_error_to_errno (ntoh32 (hdr->rsp.op_errno))); ret = transport_submit (trans, (char *)hdr, hdrlen, vector, count, iobref); diff --git a/xlators/protocol/server/src/server-resolve.c b/xlators/protocol/server/src/server-resolve.c index f7a2205e588..0db29468ffd 100644 --- a/xlators/protocol/server/src/server-resolve.c +++ b/xlators/protocol/server/src/server-resolve.c @@ -524,6 +524,8 @@ server_resolve_done (call_frame_t *frame) state = CALL_STATE (frame); bound_xl = BOUND_XL (frame); + server_print_request (frame); + state->resume_fn (frame, bound_xl); return 0; @@ -581,13 +583,6 @@ resolve_and_resume (call_frame_t *frame, server_resume_fn_t fn) this = frame->this; - gf_log (BOUND_XL (frame)->name, GF_LOG_DEBUG, - "RESOLVE %s() on %s %s", - gf_fop_list[frame->root->op], - state->resolve.path, state->resolve2.path); - - print_server_state (frame, state, this, 1); - server_resolve_all (frame); return 0; -- cgit