From: Christian Hopps Date: Fri, 9 Jun 2023 20:54:54 +0000 (-0400) Subject: lib: mgmtd: improvements in logging and commentary X-Git-Tag: base_9.1~363^2 X-Git-Url: https://git.puffer.fish/?a=commitdiff_plain;h=96f9e7853bad7e21676f2eb126a915561e6c8dce;p=matthieu%2Ffrr.git lib: mgmtd: improvements in logging and commentary - log names of datastores not numbers - improve logging for mgmt_msg_read - Rather than use a bool, instead store the pending const string name of the command being run that has postponed the CLI. This adds some nice information to the logging when enabled. Signed-off-by: Christian Hopps --- diff --git a/lib/mgmt_be_client.c b/lib/mgmt_be_client.c index 24084f6fe8..c8ea850e35 100644 --- a/lib/mgmt_be_client.c +++ b/lib/mgmt_be_client.c @@ -20,14 +20,6 @@ #include "lib/mgmt_be_client_clippy.c" -#define MGMTD_BE_CLIENT_DBG(fmt, ...) \ - DEBUGD(&mgmt_dbg_be_client, "BE-CLIENT: %s: " fmt, __func__, \ - ##__VA_ARGS__) -#define MGMTD_BE_CLIENT_ERR(fmt, ...) \ - zlog_err("BE-CLIENT: %s: ERROR: " fmt, __func__, ##__VA_ARGS__) -#define MGMTD_DBG_BE_CLIENT_CHECK() \ - DEBUG_MODE_CHECK(&mgmt_dbg_be_client, DEBUG_MODE_ALL) - DEFINE_MTYPE_STATIC(LIB, MGMTD_BE_CLIENT, "backend client"); DEFINE_MTYPE_STATIC(LIB, MGMTD_BE_CLIENT_NAME, "backend client name"); DEFINE_MTYPE_STATIC(LIB, MGMTD_BE_BATCH, "backend transaction batch data"); diff --git a/lib/mgmt_be_client.h b/lib/mgmt_be_client.h index 4d8a1f51a1..4ad5ca5957 100644 --- a/lib/mgmt_be_client.h +++ b/lib/mgmt_be_client.h @@ -131,10 +131,20 @@ mgmt_be_client_name2id(const char *name) return MGMTD_BE_CLIENT_ID_MAX; } +extern struct debug mgmt_dbg_be_client; + /*************************************************************** * API prototypes ***************************************************************/ +#define MGMTD_BE_CLIENT_DBG(fmt, ...) \ + DEBUGD(&mgmt_dbg_be_client, "BE-CLIENT: %s: " fmt, __func__, \ + ##__VA_ARGS__) +#define MGMTD_BE_CLIENT_ERR(fmt, ...) \ + zlog_err("BE-CLIENT: %s: ERROR: " fmt, __func__, ##__VA_ARGS__) +#define MGMTD_DBG_BE_CLIENT_CHECK() \ + DEBUG_MODE_CHECK(&mgmt_dbg_be_client, DEBUG_MODE_ALL) + /** * Create backend client and connect to MGMTD. * diff --git a/lib/mgmt_fe_client.c b/lib/mgmt_fe_client.c index 7af421405b..be7263f21b 100644 --- a/lib/mgmt_fe_client.c +++ b/lib/mgmt_fe_client.c @@ -50,6 +50,22 @@ struct mgmt_fe_client { struct debug mgmt_dbg_fe_client = {0, "Management frontend client operations"}; +static inline const char *dsid2name(Mgmtd__DatastoreId id) +{ + switch ((int)id) { + case MGMTD_DS_NONE: + return "none"; + case MGMTD_DS_RUNNING: + return "running"; + case MGMTD_DS_CANDIDATE: + return "candidate"; + case MGMTD_DS_OPERATIONAL: + return "operational"; + default: + return "unknown-datastore-id"; + } +} + static struct mgmt_fe_client_session * mgmt_fe_find_session_by_client_id(struct mgmt_fe_client *client, uint64_t client_id) @@ -165,8 +181,9 @@ int mgmt_fe_send_lockds_req(struct mgmt_fe_client *client, uint64_t session_id, fe_msg.lockds_req = &lockds_req; MGMTD_FE_CLIENT_DBG( - "Sending %sLOCK_REQ message for Ds:%d session-id %" PRIu64, - lock ? "" : "UN", ds_id, session_id); + "Sending LOCKDS_REQ (%sLOCK) message for DS:%s session-id %" PRIu64, + lock ? "" : "UN", dsid2name(ds_id), session_id); + return mgmt_fe_client_send_msg(client, &fe_msg, false); } @@ -194,9 +211,9 @@ int mgmt_fe_send_setcfg_req(struct mgmt_fe_client *client, uint64_t session_id, fe_msg.setcfg_req = &setcfg_req; MGMTD_FE_CLIENT_DBG( - "Sending SET_CONFIG_REQ message for Ds:%d session-id %" PRIu64 + "Sending SET_CONFIG_REQ message for DS:%s session-id %" PRIu64 " (#xpaths:%d)", - ds_id, session_id, num_data_reqs); + dsid2name(ds_id), session_id, num_data_reqs); return mgmt_fe_client_send_msg(client, &fe_msg, false); } @@ -224,8 +241,8 @@ int mgmt_fe_send_commitcfg_req(struct mgmt_fe_client *client, fe_msg.commcfg_req = &commitcfg_req; MGMTD_FE_CLIENT_DBG( - "Sending COMMIT_CONFIG_REQ message for Src-Ds:%d, Dst-Ds:%d session-id %" PRIu64, - src_ds_id, dest_ds_id, session_id); + "Sending COMMIT_CONFIG_REQ message for Src-DS:%s, Dst-DS:%s session-id %" PRIu64, + dsid2name(src_ds_id), dsid2name(dest_ds_id), session_id); return mgmt_fe_client_send_msg(client, &fe_msg, false); } @@ -251,9 +268,9 @@ int mgmt_fe_send_getcfg_req(struct mgmt_fe_client *client, uint64_t session_id, fe_msg.getcfg_req = &getcfg_req; MGMTD_FE_CLIENT_DBG( - "Sending GET_CONFIG_REQ message for Ds:%d session-id %" PRIu64 + "Sending GET_CONFIG_REQ message for DS:%s session-id %" PRIu64 " (#xpaths:%d)", - ds_id, session_id, num_data_reqs); + dsid2name(ds_id), session_id, num_data_reqs); return mgmt_fe_client_send_msg(client, &fe_msg, false); } @@ -279,9 +296,9 @@ int mgmt_fe_send_getdata_req(struct mgmt_fe_client *client, uint64_t session_id, fe_msg.getdata_req = &getdata_req; MGMTD_FE_CLIENT_DBG( - "Sending GET_CONFIG_REQ message for Ds:%d session-id %" PRIu64 + "Sending GET_CONFIG_REQ message for DS:%s session-id %" PRIu64 " (#xpaths:%d)", - ds_id, session_id, num_data_reqs); + dsid2name(ds_id), session_id, num_data_reqs); return mgmt_fe_client_send_msg(client, &fe_msg, false); } diff --git a/lib/mgmt_fe_client.h b/lib/mgmt_fe_client.h index 845d0bd94a..b0ac44bb3e 100644 --- a/lib/mgmt_fe_client.h +++ b/lib/mgmt_fe_client.h @@ -119,6 +119,10 @@ struct mgmt_fe_client_cbs { extern struct debug mgmt_dbg_fe_client; +/*************************************************************** + * API prototypes + ***************************************************************/ + #define MGMTD_FE_CLIENT_DBG(fmt, ...) \ DEBUGD(&mgmt_dbg_fe_client, "FE-CLIENT: %s: " fmt, __func__, \ ##__VA_ARGS__) @@ -127,11 +131,6 @@ extern struct debug mgmt_dbg_fe_client; #define MGMTD_DBG_FE_CLIENT_CHECK() \ DEBUG_MODE_CHECK(&mgmt_dbg_fe_client, DEBUG_MODE_ALL) - -/*************************************************************** - * API prototypes - ***************************************************************/ - /* * Initialize library and try connecting with MGMTD FrontEnd interface. * diff --git a/lib/mgmt_msg.c b/lib/mgmt_msg.c index 0d9802a2b3..ba69c20aba 100644 --- a/lib/mgmt_msg.c +++ b/lib/mgmt_msg.c @@ -59,11 +59,12 @@ enum mgmt_msg_rsched mgmt_msg_read(struct mgmt_msg_state *ms, int fd, */ while (avail > sizeof(struct mgmt_msg_hdr)) { n = stream_read_try(ms->ins, fd, avail); - MGMT_MSG_DBG(dbgtag, "got %zd bytes", n); /* -2 is normal nothing read, and to retry */ - if (n == -2) + if (n == -2) { + MGMT_MSG_DBG(dbgtag, "nothing more to read"); break; + } if (n <= 0) { if (n == 0) MGMT_MSG_ERR(ms, "got EOF/disconnect"); @@ -73,6 +74,7 @@ enum mgmt_msg_rsched mgmt_msg_read(struct mgmt_msg_state *ms, int fd, safe_strerror(errno)); return MSR_DISCONNECT; } + MGMT_MSG_DBG(dbgtag, "read %zd bytes", n); ms->nrxb += n; avail -= n; } diff --git a/lib/vty.c b/lib/vty.c index cbf42de473..972d004cfb 100644 --- a/lib/vty.c +++ b/lib/vty.c @@ -134,18 +134,22 @@ void vty_mgmt_resume_response(struct vty *vty, bool success) uint8_t header[4] = {0, 0, 0, 0}; int ret = CMD_SUCCESS; - if (!vty->mgmt_req_pending) { + if (!vty->mgmt_req_pending_cmd) { zlog_err( - "vty response called without setting mgmt_req_pending"); + "vty resume response called without mgmt_req_pending_cmd"); return; } if (!success) ret = CMD_WARNING_CONFIG_FAILED; - vty->mgmt_req_pending = false; + MGMTD_FE_CLIENT_DBG( + "resuming CLI cmd after %s on vty session-id: %" PRIu64 + " with '%s'", + vty->mgmt_req_pending_cmd, vty->mgmt_session_id, + success ? "succeeded" : "failed"); - MGMTD_FE_CLIENT_DBG("resuming: %s:", success ? "succeeded" : "failed"); + vty->mgmt_req_pending_cmd = NULL; if (vty->type != VTY_FILE) { header[3] = ret; @@ -2274,6 +2278,19 @@ static void vtysh_read(struct event *thread) sock = EVENT_FD(thread); vty = EVENT_ARG(thread); + /* + * This code looks like it can read multiple commands from the `buf` + * value returned by read(); however, it cannot in some cases. + * + * There are multiple paths out of the "copying to vty->buf" loop, which + * lose any content not yet copied from the stack `buf`, `passfd`, + * `CMD_SUSPEND` and finally if a front-end for mgmtd (generally this + * would be mgmtd itself). So these code paths are counting on vtysh not + * sending us more than 1 command line before waiting on the reply to + * that command. + */ + assert(vty->type == VTY_SHELL_SERV); + if ((nbytes = read(sock, buf, VTY_READ_BUFSIZ)) <= 0) { if (nbytes < 0) { if (ERRNO_IO_RETRY(errno)) { @@ -2348,8 +2365,13 @@ static void vtysh_read(struct event *thread) /* with new infra we need to stop response till * we get response through callback. */ - if (vty->mgmt_req_pending) + if (vty->mgmt_req_pending_cmd) { + MGMTD_FE_CLIENT_DBG( + "postpone CLI cmd response pending mgmtd %s on vty session-id %" PRIu64, + vty->mgmt_req_pending_cmd, + vty->mgmt_session_id); return; + } /* warning: watchfrr hardcodes this result write */ @@ -3624,7 +3646,7 @@ int vty_mgmt_send_lockds_req(struct vty *vty, Mgmtd__DatastoreId ds_id, return -1; } - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "MESSAGE_LOCKDS_REQ"; } return 0; @@ -3724,7 +3746,7 @@ int vty_mgmt_send_config_data(struct vty *vty) return -1; } - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "MESSAGE_SETCFG_REQ"; } return 0; @@ -3744,7 +3766,7 @@ int vty_mgmt_send_commit_config(struct vty *vty, bool validate_only, bool abort) return -1; } - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "MESSAGE_COMMCFG_REQ"; vty->mgmt_num_pending_setcfg = 0; } @@ -3781,7 +3803,7 @@ int vty_mgmt_send_get_config(struct vty *vty, Mgmtd__DatastoreId datastore, return -1; } - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "MESSAGE_GETCFG_REQ"; return 0; } @@ -3815,7 +3837,7 @@ int vty_mgmt_send_get_data(struct vty *vty, Mgmtd__DatastoreId datastore, return -1; } - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "MESSAGE_GETDATA_REQ"; return 0; } diff --git a/lib/vty.h b/lib/vty.h index 28f27d0d47..2b9ee4838e 100644 --- a/lib/vty.h +++ b/lib/vty.h @@ -229,7 +229,7 @@ struct vty { /* set when we have sent mgmtd a *REQ command in response to some vty * CLI command and we are waiting on the reply so we can respond to the * vty user. */ - bool mgmt_req_pending; + const char *mgmt_req_pending_cmd; bool mgmt_locked_candidate_ds; }; diff --git a/mgmtd/mgmt_ds.c b/mgmtd/mgmt_ds.c index 2926c9dd4f..5a4b00d309 100644 --- a/mgmtd/mgmt_ds.c +++ b/mgmtd/mgmt_ds.c @@ -80,7 +80,9 @@ static int mgmt_ds_replace_dst_with_src_ds(struct mgmt_ds_ctx *src, if (!src || !dst) return -1; - MGMTD_DS_DBG("Replacing %d with %d", dst->ds_id, src->ds_id); + + MGMTD_DS_DBG("Replacing %s with %s", mgmt_ds_id2name(dst->ds_id), + mgmt_ds_id2name(src->ds_id)); src_dnode = src->config_ds ? src->root.cfg_root->dnode : dst->root.dnode_root; diff --git a/mgmtd/mgmt_fe_adapter.c b/mgmtd/mgmt_fe_adapter.c index eb23fc3d60..e9cbd444e8 100644 --- a/mgmtd/mgmt_fe_adapter.c +++ b/mgmtd/mgmt_fe_adapter.c @@ -17,6 +17,7 @@ #include "hash.h" #include "jhash.h" #include "mgmtd/mgmt.h" +#include "mgmtd/mgmt_ds.h" #include "mgmtd/mgmt_memory.h" #include "mgmtd/mgmt_fe_adapter.h" @@ -74,18 +75,19 @@ mgmt_fe_session_write_lock_ds(Mgmtd__DatastoreId ds_id, if (!session->ds_write_locked[ds_id]) { if (mgmt_ds_write_lock(ds_ctx) != 0) { MGMTD_FE_ADAPTER_DBG( - "Failed to lock the DS %u for session-id: %" PRIu64 + "Failed to lock the DS:%s for session-id: %" PRIu64 " from %s!", - ds_id, session->session_id, + mgmt_ds_id2name(ds_id), session->session_id, session->adapter->name); return -1; } session->ds_write_locked[ds_id] = true; MGMTD_FE_ADAPTER_DBG( - "Write-Locked the DS %u for session-id: %" PRIu64 + "Write-Locked the DS:%s for session-id: %" PRIu64 " from %s", - ds_id, session->session_id, session->adapter->name); + mgmt_ds_id2name(ds_id), session->session_id, + session->adapter->name); } return 0; @@ -99,18 +101,19 @@ mgmt_fe_session_read_lock_ds(Mgmtd__DatastoreId ds_id, if (!session->ds_read_locked[ds_id]) { if (mgmt_ds_read_lock(ds_ctx) != 0) { MGMTD_FE_ADAPTER_DBG( - "Failed to lock the DS %u for session-is: %" PRIu64 + "Failed to lock the DS:%s for session-is: %" PRIu64 " from %s", - ds_id, session->session_id, + mgmt_ds_id2name(ds_id), session->session_id, session->adapter->name); return -1; } session->ds_read_locked[ds_id] = true; MGMTD_FE_ADAPTER_DBG( - "Read-Locked the DS %u for session-id: %" PRIu64 + "Read-Locked the DS:%s for session-id: %" PRIu64 " from %s", - ds_id, session->session_id, session->adapter->name); + mgmt_ds_id2name(ds_id), session->session_id, + session->adapter->name); } return 0; @@ -126,33 +129,35 @@ static int mgmt_fe_session_unlock_ds(Mgmtd__DatastoreId ds_id, session->ds_locked_implict[ds_id] = false; if (mgmt_ds_unlock(ds_ctx) != 0) { MGMTD_FE_ADAPTER_DBG( - "Failed to unlock the DS %u taken earlier by session-id: %" PRIu64 + "Failed to unlock the DS:%s taken earlier by session-id: %" PRIu64 " from %s", - ds_id, session->session_id, + mgmt_ds_id2name(ds_id), session->session_id, session->adapter->name); return -1; } MGMTD_FE_ADAPTER_DBG( - "Unlocked DS %u write-locked earlier by session-id: %" PRIu64 + "Unlocked DS:%s write-locked earlier by session-id: %" PRIu64 " from %s", - ds_id, session->session_id, session->adapter->name); + mgmt_ds_id2name(ds_id), session->session_id, + session->adapter->name); } else if (unlock_read && session->ds_read_locked[ds_id]) { session->ds_read_locked[ds_id] = false; session->ds_locked_implict[ds_id] = false; if (mgmt_ds_unlock(ds_ctx) != 0) { MGMTD_FE_ADAPTER_DBG( - "Failed to unlock the DS %u taken earlier by session-id: %" PRIu64 + "Failed to unlock the DS:%s taken earlier by session-id: %" PRIu64 " from %s", - ds_id, session->session_id, + mgmt_ds_id2name(ds_id), session->session_id, session->adapter->name); return -1; } MGMTD_FE_ADAPTER_DBG( - "Unlocked DS %u read-locked earlier by session-id: %" PRIu64 + "Unlocked DS:%s read-locked earlier by session-id: %" PRIu64 " from %s", - ds_id, session->session_id, session->adapter->name); + mgmt_ds_id2name(ds_id), session->session_id, + session->adapter->name); } return 0; @@ -1148,7 +1153,7 @@ static int mgmt_fe_session_handle_commit_config_req_msg( } /* - * Next check first if the COMMCFG_REQ is for Candidate DS + * Next check first if the COMMCFG_REQ is for running DS * or not. Report failure if its not. MGMTD currently only * supports editing the Candidate DS. */ @@ -1278,10 +1283,10 @@ mgmt_fe_adapter_handle_msg(struct mgmt_fe_client_adapter *adapter, session = mgmt_session_id2ctx( fe_msg->lockds_req->session_id); MGMTD_FE_ADAPTER_DBG( - "Got %sLOCKDS_REQ for DS:%d for session-id %" PRIu64 + "Got LOCKDS_REQ (%sLOCK) for DS:%s for session-id %" PRIu64 " from '%s'", fe_msg->lockds_req->lock ? "" : "UN", - fe_msg->lockds_req->ds_id, + mgmt_ds_id2name(fe_msg->lockds_req->ds_id), fe_msg->lockds_req->session_id, adapter->name); mgmt_fe_session_handle_lockds_req_msg( session, fe_msg->lockds_req); @@ -1291,11 +1296,11 @@ mgmt_fe_adapter_handle_msg(struct mgmt_fe_client_adapter *adapter, fe_msg->setcfg_req->session_id); session->adapter->setcfg_stats.set_cfg_count++; MGMTD_FE_ADAPTER_DBG( - "Got SETCFG_REQ (%d Xpaths, Implicit:%c) on DS:%d for session-id %" PRIu64 + "Got SETCFG_REQ (%d Xpaths, Implicit:%c) on DS:%s for session-id %" PRIu64 " from '%s'", (int)fe_msg->setcfg_req->n_data, fe_msg->setcfg_req->implicit_commit ? 'T' : 'F', - fe_msg->setcfg_req->ds_id, + mgmt_ds_id2name(fe_msg->setcfg_req->ds_id), fe_msg->setcfg_req->session_id, adapter->name); mgmt_fe_session_handle_setcfg_req_msg( @@ -1305,10 +1310,10 @@ mgmt_fe_adapter_handle_msg(struct mgmt_fe_client_adapter *adapter, session = mgmt_session_id2ctx( fe_msg->commcfg_req->session_id); MGMTD_FE_ADAPTER_DBG( - "Got COMMCFG_REQ for src-DS:%d dst-DS:%d (Abort:%c) on session-id %" PRIu64 + "Got COMMCFG_REQ for src-DS:%s dst-DS:%s (Abort:%c) on session-id %" PRIu64 " from '%s'", - fe_msg->commcfg_req->src_ds_id, - fe_msg->commcfg_req->dst_ds_id, + mgmt_ds_id2name(fe_msg->commcfg_req->src_ds_id), + mgmt_ds_id2name(fe_msg->commcfg_req->dst_ds_id), fe_msg->commcfg_req->abort ? 'T' : 'F', fe_msg->commcfg_req->session_id, adapter->name); mgmt_fe_session_handle_commit_config_req_msg( @@ -1318,9 +1323,9 @@ mgmt_fe_adapter_handle_msg(struct mgmt_fe_client_adapter *adapter, session = mgmt_session_id2ctx( fe_msg->getcfg_req->session_id); MGMTD_FE_ADAPTER_DBG( - "Got GETCFG_REQ for DS:%d (xpaths: %d) on session-id %" PRIu64 + "Got GETCFG_REQ for DS:%s (xpaths: %d) on session-id %" PRIu64 " from '%s'", - fe_msg->getcfg_req->ds_id, + mgmt_ds_id2name(fe_msg->getcfg_req->ds_id), (int)fe_msg->getcfg_req->n_data, fe_msg->getcfg_req->session_id, adapter->name); mgmt_fe_session_handle_getcfg_req_msg( @@ -1330,9 +1335,9 @@ mgmt_fe_adapter_handle_msg(struct mgmt_fe_client_adapter *adapter, session = mgmt_session_id2ctx( fe_msg->getdata_req->session_id); MGMTD_FE_ADAPTER_DBG( - "Got GETDATA_REQ for DS:%d (xpaths: %d) on session-id %" PRIu64 + "Got GETDATA_REQ for DS:%s (xpaths: %d) on session-id %" PRIu64 " from '%s'", - fe_msg->getdata_req->ds_id, + mgmt_ds_id2name(fe_msg->getdata_req->ds_id), (int)fe_msg->getdata_req->n_data, fe_msg->getdata_req->session_id, adapter->name); mgmt_fe_session_handle_getdata_req_msg( diff --git a/mgmtd/mgmt_history.c b/mgmtd/mgmt_history.c index ab84b1efcf..54eb45fdf4 100644 --- a/mgmtd/mgmt_history.c +++ b/mgmtd/mgmt_history.c @@ -248,7 +248,7 @@ static int mgmt_history_rollback_to_cmt(struct vty *vty, * is completed. On rollback completion mgmt_history_rollback_complete() * shall be called to resume the rollback command return to VTYSH. */ - vty->mgmt_req_pending = true; + vty->mgmt_req_pending_cmd = "ROLLBACK"; rollback_vty = vty; return 0; }