From ed5ddbb68d23599a065568f0f47e4cd175dbe01b Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Sat, 29 Jan 2022 15:41:41 +0800 Subject: Add conn_xxx() macros to print connection info in more details conn_info() conn_warn() conn_error() and conn_debug() are added. conn_xxx() macros would print session id and connection id in log. Signed-off-by: Wenchao Hao --- usr/initiator.h | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) (limited to 'usr') diff --git a/usr/initiator.h b/usr/initiator.h index dbf6f2b..a4e01a2 100644 --- a/usr/initiator.h +++ b/usr/initiator.h @@ -32,6 +32,7 @@ #include "config.h" #include "actor.h" #include "list.h" +#include "log.h" #define ISCSI_CONFIG_ROOT "/etc/iscsi/" @@ -45,6 +46,46 @@ #define LOCK_FILE LOCK_DIR"/lock" #define LOCK_WRITE_FILE LOCK_DIR"/lock.write" +#define conn_info(conn, fmt, ...) \ +do { \ + if (conn->session == NULL) { \ + log_info(fmt, ##__VA_ARGS__); \ + break; \ + } \ + log_info("connection%d:%d " fmt, \ + conn->session->id, conn->id, ##__VA_ARGS__); \ +} while(0) + +#define conn_warn(conn, fmt, ...) \ +do { \ + if (conn->session == NULL) { \ + log_warning(fmt, ##__VA_ARGS__); \ + break; \ + } \ + log_warning("connection%d:%d " fmt, \ + conn->session->id, conn->id, ##__VA_ARGS__); \ +} while(0) + +#define conn_error(conn, fmt, ...) \ +do { \ + if (conn->session == NULL) { \ + log_error(fmt, ##__VA_ARGS__); \ + break; \ + } \ + log_error("connection%d:%d " fmt, \ + conn->session->id, conn->id, ##__VA_ARGS__); \ +} while(0) + +#define conn_debug(level, conn, fmt, ...) \ +do { \ + if (conn->session == NULL) { \ + log_debug(level, fmt, ##__VA_ARGS__); \ + break; \ + } \ + log_debug(level, "connection%d:%d " fmt, \ + conn->session->id, conn->id, ##__VA_ARGS__); \ +} while(0) + typedef enum iscsi_session_r_stage_e { R_STAGE_NO_CHANGE, R_STAGE_SESSION_CLEANUP, -- cgit v1.2.1 From 4c27f41792bc146ea61472527db0990268b0916d Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Thu, 10 Feb 2022 15:40:06 +0800 Subject: Make session and connect log readable and helpful to locate problem There are many logs like following which are not helpful to locate problem when there are multiple sessions: "unsupported opcode 0xxxx" We can not know which connection the log belongs to, so this commit find these logs in initiator.c and add session id, connection id for them. Signed-off-by: Wenchao Hao --- usr/initiator.c | 192 ++++++++++++++++++++++++++++---------------------------- 1 file changed, 95 insertions(+), 97 deletions(-) (limited to 'usr') diff --git a/usr/initiator.c b/usr/initiator.c index 40d297f..503ccba 100644 --- a/usr/initiator.c +++ b/usr/initiator.c @@ -99,7 +99,7 @@ static void iscsi_ev_context_free(iscsi_conn_t *conn) if (conn->context_pool[i]->allocated) /* missing flush on shutdown */ - log_error("BUG: context_pool leak %p", + conn_error(conn, "BUG: context_pool leak %p", conn->context_pool[i]); free(conn->context_pool[i]); } @@ -127,7 +127,7 @@ iscsi_ev_context_get(iscsi_conn_t *conn, int ev_size) /* some callers abuse this pointer */ ev_context->data = (void *)ev_context + sizeof(struct iscsi_ev_context); - log_debug(7, "get ev context %p", + conn_debug(7, conn, "get ev context %p", &ev_context->actor); return ev_context; } @@ -162,8 +162,7 @@ __login_response_status(iscsi_conn_t *conn, case LOGIN_REDIRECTION_FAILED: return CONN_LOGIN_RETRY; default: - log_error("Login error (Login status %d) on conn %d", conn->id, - login_status); + conn_error(conn, "Login error (Login status %d)", login_status); break; } @@ -193,9 +192,8 @@ __check_iscsi_status_class(iscsi_session_t *session, int cid, conn->failback_saddr = conn->saddr; return CONN_LOGIN_IMM_REDIRECT_RETRY; default: - log_error("conn %d login rejected: redirection " - "type 0x%x not supported", - conn->id, status_detail); + conn_error(conn, "login rejected: redirection " + "type 0x%x not supported", status_detail); return CONN_LOGIN_RETRY; } case ISCSI_STATUS_CLS_INITIATOR_ERR: @@ -206,13 +204,13 @@ __check_iscsi_status_class(iscsi_session_t *session, int cid, session->id); return CONN_LOGIN_AUTH_FAILED; case ISCSI_LOGIN_STATUS_TGT_FORBIDDEN: - log_error("conn %d login rejected: initiator " - "failed authorization with target", conn->id); + conn_error(conn, "login rejected: initiator " + "failed authorization with target"); return CONN_LOGIN_AUTH_FAILED; case ISCSI_LOGIN_STATUS_TGT_NOT_FOUND: - log_error("conn %d login rejected: initiator " + conn_error(conn, "login rejected: initiator " "error - target not found (%02x/%02x)", - conn->id, status_class, status_detail); + status_class, status_detail); return CONN_LOGIN_FAILED; case ISCSI_LOGIN_STATUS_NO_VERSION: /* @@ -220,29 +218,26 @@ __check_iscsi_status_class(iscsi_session_t *session, int cid, * before we log an error, try the other supported * versions. */ - log_error("conn %d login rejected: incompatible " + conn_error(conn, "login rejected: incompatible " "version (%02x/%02x), non-retryable, " - "giving up", conn->id, status_class, - status_detail); + "giving up", status_class, status_detail); return CONN_LOGIN_FAILED; default: - log_error("conn %d login rejected: initiator " - "error (%02x/%02x)", conn->id, status_class, - status_detail); + conn_error(conn, "login rejected: initiator " + "error (%02x/%02x)", status_class, status_detail); return CONN_LOGIN_FAILED; } case ISCSI_STATUS_CLS_TARGET_ERR: - log_error("conn %d login rejected: target error " - "(%02x/%02x)", conn->id, status_class, status_detail); + conn_error(conn, "login rejected: target error " + "(%02x/%02x)", status_class, status_detail); /* * We have no idea what the problem is. But spec says initiator * may retry later. */ return CONN_LOGIN_RETRY; default: - log_error("conn %d login response with unknown status " - "class 0x%x, detail 0x%x", conn->id, status_class, - status_detail); + conn_error(conn, "login response with unknown status " + "class 0x%x, detail 0x%x", status_class, status_detail); break; } @@ -257,8 +252,9 @@ __session_conn_create(iscsi_session_t *session, int cid) node_rec_t *rec = &session->nrec; int err; + conn->id = cid; if (iscsi_ev_context_alloc(conn)) { - log_error("cannot allocate context_pool for conn cid %d", cid); + conn_error(conn, "cannot allocate context_pool"); return ISCSI_ERR_NOMEM; } @@ -277,10 +273,9 @@ __session_conn_create(iscsi_session_t *session, int cid) conn->socket_fd = -1; conn->transport_ep_handle = -1; /* connection's timeouts */ - conn->id = cid; conn->logout_timeout = conn_rec->timeo.logout_timeout; if (!conn->logout_timeout) { - log_error("Invalid timeo.logout_timeout. Must be greater " + conn_error(conn, "Invalid timeo.logout_timeout. Must be greater " "than zero. Using default %d.", DEF_LOGOUT_TIMEO); conn->logout_timeout = DEF_LOGOUT_TIMEO; @@ -288,7 +283,7 @@ __session_conn_create(iscsi_session_t *session, int cid) conn->login_timeout = conn_rec->timeo.login_timeout; if (!conn->login_timeout) { - log_error("Invalid timeo.login_timeout. Must be greater " + conn_error(conn, "Invalid timeo.login_timeout. Must be greater " "than zero. Using default %d.", DEF_LOGIN_TIMEO); conn->login_timeout = DEF_LOGIN_TIMEO; @@ -300,14 +295,14 @@ __session_conn_create(iscsi_session_t *session, int cid) conn->noop_out_interval = conn_rec->timeo.noop_out_interval; conn->noop_out_timeout = conn_rec->timeo.noop_out_timeout; if (conn->noop_out_interval && !conn->noop_out_timeout) { - log_error("Invalid timeo.noop_out_timeout. Must be greater " + conn_error(conn, "Invalid timeo.noop_out_timeout. Must be greater " "than zero. Using default %d.", DEF_NOOP_OUT_TIMEO); conn->noop_out_timeout = DEF_NOOP_OUT_TIMEO; } if (conn->noop_out_timeout && !conn->noop_out_interval) { - log_error("Invalid timeo.noop_out_interval. Must be greater " + conn_error(conn, "Invalid timeo.noop_out_interval. Must be greater " "than zero. Using default %d.", DEF_NOOP_OUT_INTERVAL); conn->noop_out_interval = DEF_NOOP_OUT_INTERVAL; @@ -330,7 +325,7 @@ __session_conn_create(iscsi_session_t *session, int cid) static void session_release(iscsi_session_t *session) { - log_debug(2, "Releasing session %p", session); + log_debug(2, "Releasing session:%d %p", session->id, session); if (session->target_alias) free(session->target_alias); @@ -453,7 +448,7 @@ static void iscsi_flush_context_pool(struct iscsi_session *session) static void __session_destroy(iscsi_session_t *session) { - log_debug(1, "destroying session"); + log_debug(1, "destroying session:%d", session->id); list_del(&session->list); iscsi_flush_context_pool(session); session_release(session); @@ -472,7 +467,7 @@ session_conn_shutdown(iscsi_conn_t *conn, queue_task_t *qtask, { iscsi_session_t *session = conn->session; - log_debug(2, "disconnect conn"); + conn_debug(2, conn, "disconnect conn"); /* this will check for a valid interconnect connection */ if (session->t->template->ep_disconnect) session->t->template->ep_disconnect(conn); @@ -486,19 +481,18 @@ session_conn_shutdown(iscsi_conn_t *conn, queue_task_t *qtask, if (conn->state == ISCSI_CONN_STATE_IN_LOGIN || conn->state == ISCSI_CONN_STATE_IN_LOGOUT || conn->state == ISCSI_CONN_STATE_LOGGED_IN) { - log_debug(2, "stop conn (conn state %d)", conn->state); + conn_debug(2, conn, "stop conn (conn state %d)", conn->state); if (ipc->stop_conn(session->t->handle, session->id, conn->id, STOP_CONN_TERM)) { - log_error("can't stop connection %d:%d (%d)", - session->id, conn->id, errno); + conn_error(conn, "can't stop connection (%d)", errno); return ISCSI_ERR_INTERNAL; } } - log_debug(2, "kdestroy conn"); + conn_debug(2, conn, "kdestroy conn"); if (ipc->destroy_conn(session->t->handle, session->id, conn->id)) { - log_error("can not safely destroy connection %d", conn->id); + conn_error(conn, "can not safely destroy connection"); return ISCSI_ERR_INTERNAL; } @@ -531,7 +525,7 @@ queue_delayed_reopen(queue_task_t *qtask, int delay) { iscsi_conn_t *conn = qtask->conn; - log_debug(4, "Requeue reopen attempt in %d secs", delay); + conn_debug(4, conn, "Requeue reopen attempt in %d secs", delay); /* * iscsi_login_eh can handle the login resched as @@ -548,7 +542,7 @@ static int iscsi_conn_connect(struct iscsi_conn *conn, queue_task_t *qtask) ev_context = iscsi_ev_context_get(conn, 0); if (!ev_context) { /* while reopening the recv pool should be full */ - log_error("BUG: __session_conn_reopen could not get conn " + conn_error(conn, "BUG: __session_conn_reopen could not get conn " "context for recv."); return ENOMEM; } @@ -563,14 +557,14 @@ static int iscsi_conn_connect(struct iscsi_conn *conn, queue_task_t *qtask) conn->host, sizeof(conn->host), serv, sizeof(serv), NI_NUMERICHOST|NI_NUMERICSERV); - log_error("cannot make a connection to %s:%s (%d,%d)", + conn_error(conn, "cannot make a connection to %s:%s (%d,%d)", conn->host, serv, rc, errno); iscsi_ev_context_put(ev_context); return ENOTCONN; } iscsi_sched_ev_context(ev_context, conn, 0, EV_CONN_POLL); - log_debug(3, "Setting login timer %p timeout %d", &conn->login_timer, + conn_debug(3, conn, "Setting login timer %p timeout %d", &conn->login_timer, conn->login_timeout); actor_timer_mod(&conn->login_timer, conn->login_timeout, qtask); return 0; @@ -629,7 +623,7 @@ __session_conn_reopen(iscsi_conn_t *conn, queue_task_t *qtask, int do_stop, return; queue_reopen: - log_debug(4, "Waiting %u seconds before trying to reconnect.", delay); + conn_debug(4, conn, "Waiting %u seconds before trying to reconnect.", delay); queue_delayed_reopen(qtask, delay); } @@ -661,7 +655,7 @@ static int iscsi_retry_initial_login(struct iscsi_conn *conn) timeout.tv_sec = initial_login_retry_max * conn->login_timeout; if (gettimeofday(&now, NULL)) { - log_error("Could not get time of day. Dropping down to " + conn_error(conn, "Could not get time of day. Dropping down to " "max retry check."); return initial_login_retry_max > conn->session->reopen_cnt; } @@ -672,7 +666,7 @@ static int iscsi_retry_initial_login(struct iscsi_conn *conn) * then it is time to give up */ if (timercmp(&now, &fail_time, >)) { - log_debug(1, "Giving up on initial login attempt after " + conn_debug(1, conn, "Giving up on initial login attempt after " "%u seconds.", initial_login_retry_max * conn->login_timeout); return 0; @@ -695,7 +689,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, struct iscsi_session *session = conn->session; int stop_flag = 0; - log_debug(3, "iscsi_login_eh"); + conn_debug(3, conn, "iscsi_login_eh"); /* * Flush polls and other events */ @@ -705,7 +699,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, case ISCSI_CONN_STATE_XPT_WAIT: switch (session->r_stage) { case R_STAGE_NO_CHANGE: - log_debug(6, "login failed ISCSI_CONN_STATE_XPT_WAIT/" + conn_debug(6, conn, "login failed ISCSI_CONN_STATE_XPT_WAIT/" "R_STAGE_NO_CHANGE"); /* timeout during initial connect. * clean connection. write ipc rsp or retry */ @@ -714,14 +708,13 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, session_conn_shutdown(conn, qtask, err); else { stop_flag = (session->id < INVALID_SESSION_ID) ? STOP_CONN_TERM : 0; - log_debug(6, "connection %p socket_fd: %d, " - "session id: %d stop_flag: %d\n", - conn, conn->socket_fd, session->id, stop_flag); + conn_debug(6, conn, "connection %p socket_fd: %d stop_flag: %d\n", + conn, conn->socket_fd, stop_flag); session_conn_reopen(conn, qtask, stop_flag); } break; case R_STAGE_SESSION_REDIRECT: - log_debug(6, "login failed ISCSI_CONN_STATE_XPT_WAIT/" + conn_debug(6, conn, "login failed ISCSI_CONN_STATE_XPT_WAIT/" "R_STAGE_SESSION_REDIRECT"); /* timeout during initial redirect connect * clean connection. write ipc rsp or retry */ @@ -732,7 +725,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, session_conn_reopen(conn, qtask, 0); break; case R_STAGE_SESSION_REOPEN: - log_debug(6, "login failed ISCSI_CONN_STATE_XPT_WAIT/" + conn_debug(6, conn, "login failed ISCSI_CONN_STATE_XPT_WAIT/" "R_STAGE_SESSION_REOPEN (reopen_cnt=%d, reopen_max=%d)", session->reopen_cnt, session->reopen_max); if (session->reopen_max && @@ -757,7 +750,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, switch (session->r_stage) { case R_STAGE_NO_CHANGE: case R_STAGE_SESSION_REDIRECT: - log_debug(6, "login failed ISCSI_CONN_STATE_IN_LOGIN/" + conn_debug(6, conn, "login failed ISCSI_CONN_STATE_IN_LOGIN/" "R_STAGE_NO_CHANGE %d", session->reopen_cnt); /* @@ -773,7 +766,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, STOP_CONN_RECOVER); break; case R_STAGE_SESSION_REOPEN: - log_debug(6, "login failed ISCSI_CONN_STATE_IN_LOGIN/" + conn_debug(6, conn, "login failed ISCSI_CONN_STATE_IN_LOGIN/" "R_STAGE_SESSION_REOPEN %d", session->reopen_cnt); session_conn_reopen(conn, qtask, STOP_CONN_RECOVER); @@ -788,7 +781,7 @@ static void iscsi_login_eh(struct iscsi_conn *conn, struct queue_task *qtask, break; default: - log_error("Ignoring login error %d in conn state %d.", + conn_error(conn, "Ignoring login error %d in conn state %d.", err, conn->state); break; } @@ -850,19 +843,19 @@ __conn_error_handle(iscsi_session_t *session, iscsi_conn_t *conn) iscsi_login_eh(conn, qtask, ISCSI_ERR_TRANS); return; } - log_debug(1, "ignoring conn error in login. " + conn_debug(1, conn, "ignoring conn error in login. " "let it timeout"); return; case ISCSI_CONN_STATE_XPT_WAIT: - log_debug(1, "ignoring conn error in XPT_WAIT. " + conn_debug(1, conn, "ignoring conn error in XPT_WAIT. " "let connection fail on its own"); return; case ISCSI_CONN_STATE_CLEANUP_WAIT: - log_debug(1, "ignoring conn error in CLEANUP_WAIT. " + conn_debug(1, conn, "ignoring conn error in CLEANUP_WAIT. " "let connection stop"); return; default: - log_debug(8, "invalid state %d", conn->state); + conn_debug(8, conn, "invalid state %d", conn->state); return; } @@ -879,6 +872,7 @@ static void session_conn_error(void *data) enum iscsi_err error = *(enum iscsi_err *)ev_context->data; iscsi_conn_t *conn = ev_context->conn; iscsi_session_t *session = conn->session; + int sid = session->id; log_warning("Kernel reported iSCSI connection %d:%d error (%d - %s) " "state (%d)", session->id, conn->id, error, @@ -889,7 +883,7 @@ static void session_conn_error(void *data) switch (error) { case ISCSI_ERR_INVALID_HOST: if (session_conn_shutdown(conn, NULL, ISCSI_SUCCESS)) - log_error("BUG: Could not shutdown session."); + log_error("BUG: Could not shutdown session:%d.", sid); break; default: __conn_error_handle(session, conn); @@ -919,7 +913,7 @@ static void iscsi_login_redirect(iscsi_conn_t *conn) iscsi_session_t *session = conn->session; iscsi_login_context_t *c = &conn->login_context; - log_debug(3, "login redirect ..."); + conn_debug(3, conn, "login redirect ..."); if (session->r_stage == R_STAGE_NO_CHANGE) session->r_stage = R_STAGE_SESSION_REDIRECT; @@ -988,7 +982,7 @@ static void conn_send_nop_out(void *data) actor_timer(&conn->nop_out_timer, conn->noop_out_timeout, conn_nop_out_timeout, conn); - log_debug(3, "noop out timeout timer %p start, timeout %d", + conn_debug(3, conn, "noop out timeout timer %p start, timeout %d", &conn->nop_out_timer, conn->noop_out_timeout); } @@ -1091,7 +1085,7 @@ setup_full_feature_phase(iscsi_conn_t *conn) if (conn->userspace_nop && conn->noop_out_interval) { actor_timer(&conn->nop_out_timer, conn->noop_out_interval, conn_send_nop_out, conn); - log_debug(3, "noop out timer %p start", + conn_debug(3, conn, "noop out timer %p start", &conn->nop_out_timer); } } @@ -1106,7 +1100,7 @@ static void iscsi_logout_timedout(void *data) * assume we were in ISCSI_CONN_STATE_IN_LOGOUT or there * was some nasty error */ - log_debug(3, "logout timeout, dropping conn..."); + conn_debug(3, conn, "logout timeout, dropping conn..."); __conn_error_handle(conn->session, conn); } @@ -1132,12 +1126,13 @@ static int iscsi_send_logout(iscsi_conn_t *conn) ev_context = iscsi_ev_context_get(conn, 0); if (!ev_context) /* unbounded logout */ - log_warning("Could not allocate conn context for logout."); + log_warning("connection%d:%d Could not allocate conn context for logout.", + conn->session->id, conn->id); else { iscsi_sched_ev_context(ev_context, conn, conn->logout_timeout, EV_CONN_LOGOUT_TIMER); - log_debug(3, "logout timeout timer %u", + conn_debug(3, conn, "logout timeout timer %u", conn->logout_timeout * 1000); } @@ -1149,6 +1144,7 @@ static void iscsi_stop(void *data) struct iscsi_ev_context *ev_context = data; struct iscsi_conn *conn = ev_context->conn; int rc = 0; + int sid = conn->session->id; iscsi_ev_context_put(ev_context); @@ -1159,13 +1155,13 @@ static void iscsi_stop(void *data) rc = session_conn_shutdown(conn, conn->logout_qtask, ISCSI_SUCCESS); if (rc) - log_error("BUG: Could not shutdown session."); + log_error("BUG: Could not shutdown session:%d.", sid); } static void iscsi_recv_nop_in(iscsi_conn_t *conn, struct iscsi_hdr *hdr) { if (!conn->userspace_nop) { - log_error("Got nop in, but kernel supports nop handling."); + conn_error(conn, "Got nop in, but kernel supports nop handling."); return; } @@ -1178,7 +1174,7 @@ static void iscsi_recv_nop_in(iscsi_conn_t *conn, struct iscsi_hdr *hdr) } else /* noop in req */ if (!__send_nopin_rsp(conn, (struct iscsi_nopin*)hdr, conn->data)) { - log_error("can not send nopin response"); + conn_error(conn, "can not send nopin response"); } } @@ -1186,10 +1182,10 @@ static void iscsi_recv_logout_rsp(iscsi_conn_t *conn, struct iscsi_hdr *hdr) { struct iscsi_logout_rsp *logout_rsp = (struct iscsi_logout_rsp *)hdr; - log_debug(3, "Recv: logout response %d", logout_rsp->response); + conn_debug(3, conn, "Recv: logout response %d", logout_rsp->response); if (logout_rsp->response == 2 || logout_rsp->response == 3) { conn->session->def_time2wait = ntohs(logout_rsp->t2wait); - log_debug(4, "logout rsp returned time2wait %u", + conn_debug(4, conn, "logout rsp returned time2wait %u", conn->session->def_time2wait); } /* TODO process the hdr */ @@ -1204,7 +1200,7 @@ static void iscsi_recv_async_msg(iscsi_conn_t *conn, struct iscsi_hdr *hdr) unsigned int senselen; struct scsi_sense_hdr sshdr; - log_debug(3, "Read AEN %d", async_hdr->async_event); + conn_debug(3, conn, "Read AEN %d", async_hdr->async_event); switch (async_hdr->async_event) { case ISCSI_ASYNC_MSG_SCSI_EVENT: @@ -1212,7 +1208,7 @@ static void iscsi_recv_async_msg(iscsi_conn_t *conn, struct iscsi_hdr *hdr) buf += 2; if (!scsi_normalize_sense((uint8_t *)buf, senselen, &sshdr)) { - log_error("Could not handle AEN %d. Invalid sense.", + conn_error(conn, "Could not handle AEN %d. Invalid sense.", async_hdr->async_event); break; } @@ -1222,15 +1218,13 @@ static void iscsi_recv_async_msg(iscsi_conn_t *conn, struct iscsi_hdr *hdr) session_scan_host(session, session->hostno, NULL); break; case ISCSI_ASYNC_MSG_REQUEST_LOGOUT: - log_warning("Target requests logout within %u seconds for " - "connection", ntohs(async_hdr->param3)); + conn_warn(conn, "Target requests logout within %u seconds" , ntohs(async_hdr->param3)); if (iscsi_send_logout(conn)) - log_error("Could not send logout in response to" + conn_error(conn, "Could not send logout in response to" "logout request aen"); break; case ISCSI_ASYNC_MSG_DROPPING_CONNECTION: - log_warning("Target dropping connection %u, reconnect min %u " - "max %u", ntohs(async_hdr->param1), + conn_warn(conn, "Target dropping %u, reconnect min %u max %u", ntohs(async_hdr->param1), ntohs(async_hdr->param2), ntohs(async_hdr->param3)); session->def_time2wait = (uint32_t)ntohs(async_hdr->param2) & 0x0000FFFFFL; @@ -1244,7 +1238,7 @@ static void iscsi_recv_async_msg(iscsi_conn_t *conn, struct iscsi_hdr *hdr) break; case ISCSI_ASYNC_MSG_PARAM_NEGOTIATION: log_warning("Received async event param negotiation, " - "dropping session"); + "dropping session:%d", session->id); __conn_error_handle(session, conn); break; case ISCSI_ASYNC_MSG_VENDOR_SPECIFIC: @@ -1260,7 +1254,7 @@ static void iscsi_recv_login_rsp(struct iscsi_conn *conn) int err = ISCSI_ERR_FATAL_LOGIN; if (iscsi_login_rsp(session, c)) { - log_debug(1, "login_rsp ret (%d)", c->ret); + conn_debug(1, conn, "login_rsp ret (%d)", c->ret); switch (__login_response_status(conn, c->ret)) { case CONN_LOGIN_FAILED: @@ -1348,23 +1342,23 @@ static void session_conn_recv_pdu(void *data) iscsi_recv_async_msg(conn, &hdr); break; default: - log_error("unsupported opcode 0x%x", hdr.opcode); + conn_error(conn, "unsupported opcode 0x%x", hdr.opcode); break; } break; case ISCSI_CONN_STATE_XPT_WAIT: iscsi_ev_context_put(ev_context); - log_debug(1, "ignoring incoming PDU in XPT_WAIT. " + conn_debug(1, conn, "ignoring incoming PDU in XPT_WAIT. " "let connection re-establish or fail"); break; case ISCSI_CONN_STATE_CLEANUP_WAIT: iscsi_ev_context_put(ev_context); - log_debug(1, "ignoring incoming PDU in XPT_WAIT. " + conn_debug(1, conn, "ignoring incoming PDU in XPT_WAIT. " "let connection cleanup"); break; default: iscsi_ev_context_put(ev_context); - log_error("Invalid state. Dropping PDU."); + conn_error(conn, "Invalid state %d. Dropping PDU.", conn->state); } } @@ -1511,7 +1505,7 @@ static void setup_offload_login_phase(iscsi_conn_t *conn) if (ipc->start_conn(session->t->handle, session->id, conn->id, &rc) || rc) { if (rc == -EEXIST) { - log_error("Session already exists."); + conn_error(conn, "Session already exists."); session_conn_shutdown(conn, c->qtask, ISCSI_ERR_SESS_EXISTS); } else { @@ -1543,11 +1537,11 @@ static void session_conn_poll(void *data) rc = session->t->template->ep_poll(conn, 1); if (rc == 0) { - log_debug(4, "poll not connected %d", rc); + conn_debug(4, conn, "poll not connected %d", rc); ev_context = iscsi_ev_context_get(conn, 0); if (!ev_context) { /* while polling the recv pool should be full */ - log_error("BUG: session_conn_poll could not get conn " + conn_error(conn, "BUG: session_conn_poll could not get conn " "context."); iscsi_login_eh(conn, qtask, ISCSI_ERR_INTERNAL); return; @@ -1572,7 +1566,8 @@ static void session_conn_poll(void *data) err = ipc->create_conn(session->t->handle, session->id, conn->id, &conn->id); if (err) { - log_error("Can't create connection."); + log_error("Can't create connection for session%d.", + session->id); err = ISCSI_ERR_INTERNAL; goto cleanup; } @@ -1636,7 +1631,7 @@ static void session_conn_poll(void *data) return; } } else { - log_debug(4, "poll error %d", rc); + conn_debug(4, conn, "poll error %d", rc); queue_delayed_reopen(qtask, ISCSI_CONN_ERR_REOPEN_DELAY); } @@ -1708,7 +1703,8 @@ failed_login: session->notify_qtask = NULL; mgmt_ipc_write_rsp(qtask, ISCSI_ERR_LOGIN); if (ipc->destroy_conn(session->t->handle, session->id, conn->id)) - log_error("can not safely destroy connection %d", conn->id); + log_error("can not safely destroy connection%d:%d", + session->id, conn->id); if (ipc->destroy_session(session->t->handle, session->id)) log_error("can not safely destroy session %d", session->id); __session_destroy(session); @@ -1721,7 +1717,7 @@ static int iscsi_sched_ev_context(struct iscsi_ev_context *ev_context, { enum iscsi_err error; - log_debug(7, "sched conn context %p event %d, tmo %lu", + conn_debug(7, conn, "sched conn context %p event %d, tmo %lu", &ev_context->actor, event, tmo); ev_context->conn = conn; @@ -1765,7 +1761,7 @@ static int iscsi_sched_ev_context(struct iscsi_ev_context *ev_context, actor_schedule(&ev_context->actor); break; default: - log_error("Invalid event type %d.", event); + conn_error(conn, "Invalid event type %d.", event); } return 0; } @@ -2060,7 +2056,7 @@ static int session_unbind(struct iscsi_session *session) err = ipc->unbind_session(session->t->handle, session->id); if (err) /* older kernels did not support unbind */ - log_debug(2, "Could not unbind session %d.", err); + log_debug(2, "Could not unbind session%d %d.", session->id, err); return err; } @@ -2085,7 +2081,9 @@ int session_logout_task(int sid, queue_task_t *qtask) if (session->notify_qtask && (conn->state == ISCSI_CONN_STATE_XPT_WAIT) && (session->r_stage == R_STAGE_SESSION_REOPEN)) { - log_warning("session cannot be terminted because it's trying to reconnect: try again later"); + log_warning("session %d cannot be terminted because " + "it's trying to reconnect: try again later", + session->id); return ISCSI_ERR_SESSION_NOT_CONNECTED; } @@ -2100,14 +2098,14 @@ int session_logout_task(int sid, queue_task_t *qtask) (session->r_stage == R_STAGE_NO_CHANGE || session->r_stage == R_STAGE_SESSION_REDIRECT))) { invalid_state: - log_error("session in invalid state for logout. " - "Try again later"); + log_error("session %d in invalid state for logout. " + "Try again later", session->id); return ISCSI_ERR_INTERNAL; } if (dconfig->safe_logout && session_in_use(sid)) { - log_error("Session is actively in use for mounted storage, " - "and iscsid.safe_logout is configured."); + log_error("Session %d is actively in use for mounted storage, " + "and iscsid.safe_logout is configured.", session->id); return ISCSI_ERR_BUSY; } @@ -2132,7 +2130,7 @@ invalid_state: return ISCSI_SUCCESS; } - log_error("Could not send logout pdu. Dropping session"); + conn_error(conn, "Could not send logout pdu. Dropping session"); /* fallthrough */ default: rc = session_conn_shutdown(conn, qtask, ISCSI_SUCCESS); -- cgit v1.2.1 From 65935e02b171a0668ecbd51acdb7d0bb66cb7333 Mon Sep 17 00:00:00 2001 From: Wenchao Hao Date: Thu, 10 Feb 2022 17:01:11 +0800 Subject: mgmt: print connection info when write qtask response failed print session and connection id when write qtask response failed if these ids are accessible Signed-off-by: Wenchao Hao --- usr/mgmt_ipc.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) (limited to 'usr') diff --git a/usr/mgmt_ipc.c b/usr/mgmt_ipc.c index 054378e..c23bcc0 100644 --- a/usr/mgmt_ipc.c +++ b/usr/mgmt_ipc.c @@ -411,8 +411,12 @@ mgmt_ipc_write_rsp(queue_task_t *qtask, int err) } qtask->rsp.err = err; - if (write(qtask->mgmt_ipc_fd, &qtask->rsp, sizeof(qtask->rsp)) < 0) - log_error("IPC qtask write failed: %s", strerror(errno)); + if (write(qtask->mgmt_ipc_fd, &qtask->rsp, sizeof(qtask->rsp)) < 0) { + if (qtask->conn && qtask->conn->session) + conn_error(qtask->conn, "IPC qtask write failed: %s", strerror(errno)); + else + log_error("IPC qtask write failed: %s", strerror(errno)); + } mgmt_ipc_destroy_queue_task(qtask); } -- cgit v1.2.1