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 <chopps@labn.net>
(cherry picked from commit 96f9e7853bad7e21676f2eb126a915561e6c8dce)

7 files changed, 78 insertions, 36 deletions

diff --git a/lib/mgmt_be_client.c b/lib/mgmt_be_client.c
index aff67c4bf5..fdeff3ec0a 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 10a6b81a65..fd00e11c5f 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;
@@ -3722,7 +3744,7 @@ int vty_mgmt_send_config_data(struct vty *vty, bool implicit_commit)
 			return -1;
 		}
 
-		vty->mgmt_req_pending = true;
+		vty->mgmt_req_pending_cmd = "MESSAGE_SETCFG_REQ";
 	}
 
 	return 0;
@@ -3742,7 +3764,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;
 	}
 
@@ -3779,7 +3801,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;
 }
@@ -3813,7 +3835,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 3ad5c16365..3b651d20a2 100644
--- a/lib/vty.h
+++ b/lib/vty.h
@@ -228,7 +228,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;
 };