[PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[Shradha Gupta]

Allow the KVP daemon to log the KVP updates triggered in the VM
with a new debug flag(-d).
When the daemon is started with this flag, it logs updates and debug
information in syslog with loglevel LOG_DEBUG. This information comes
in handy for debugging issues where the key-value pairs for certain
pools show mismatch/incorrect values.
The distro-vendors can further consume these changes and modify the
respective service files to redirect the logs to specific files as
needed.

Signed-off-by: Shradha Gupta <shradhagupta@linux.microsoft.com>
---
 Changes in v2:
 * log the debug logs in syslog(debug) instead of a seperate file that
   we will have to maintain.
 * fix the commit message to indicate the same.
---
 tools/hv/hv_kvp_daemon.c | 80 ++++++++++++++++++++++++++++++++++++----
 1 file changed, 72 insertions(+), 8 deletions(-)

diff --git a/tools/hv/hv_kvp_daemon.c b/tools/hv/hv_kvp_daemon.c
index 04ba035d67e9..2ff34c2f6a8d 100644
--- a/tools/hv/hv_kvp_daemon.c
+++ b/tools/hv/hv_kvp_daemon.c
@@ -41,6 +41,7 @@
 #include <net/if.h>
 #include <limits.h>
 #include <getopt.h>
+#include <time.h>
 
 /*
  * KVP protocol: The user mode component first registers with the
@@ -83,6 +84,7 @@ enum {
 };
 
 static int in_hand_shake;
+static int debug_enabled;
 
 static char *os_name = "";
 static char *os_major = "";
@@ -153,6 +155,16 @@ static void kvp_release_lock(int pool)
 	}
 }
 
+static void convert_tm_to_string(char *tm_str, size_t tm_str_size)
+{
+	struct tm tm;
+	time_t t;
+
+	time(&t);
+	gmtime_r(&t, &tm);
+	strftime(tm_str, tm_str_size, "%Y-%m-%dT%H:%M:%S", &tm);
+}
+
 static void kvp_update_file(int pool)
 {
 	FILE *filep;
@@ -183,6 +195,23 @@ static void kvp_update_file(int pool)
 	kvp_release_lock(pool);
 }
 
+static void kvp_dump_initial_pools(int pool)
+{
+	char tm_str[50];
+	int i;
+
+	convert_tm_to_string(tm_str, sizeof(tm_str));
+
+	syslog(LOG_DEBUG, "===Start dumping the contents of pool %d ===\n",
+	       pool);
+
+	for (i = 0; i < kvp_file_info[pool].num_records; i++)
+		syslog(LOG_DEBUG, "[%s]: pool: %d, %d/%d key=%s val=%s\n",
+		       tm_str, pool, i, kvp_file_info[pool].num_records,
+		       kvp_file_info[pool].records[i].key,
+		       kvp_file_info[pool].records[i].value);
+}
+
 static void kvp_update_mem_state(int pool)
 {
 	FILE *filep;
@@ -270,6 +299,8 @@ static int kvp_file_init(void)
 			return 1;
 		kvp_file_info[i].num_records = 0;
 		kvp_update_mem_state(i);
+		if (debug_enabled)
+			kvp_dump_initial_pools(i);
 	}
 
 	return 0;
@@ -321,14 +352,28 @@ static int kvp_key_delete(int pool, const __u8 *key, int key_size)
 static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,
 				 const __u8 *value, int value_size)
 {
-	int i;
-	int num_records;
 	struct kvp_record *record;
+	int num_records;
+	char tm_str[50];
 	int num_blocks;
+	int i;
+
+	if (debug_enabled) {
+		convert_tm_to_string(tm_str, sizeof(tm_str));
+		syslog(LOG_DEBUG, "[%s]:%s: got a KVP: pool=%d key=%s val=%s",
+		       tm_str, __func__, pool, key, value);
+	}
 
 	if ((key_size > HV_KVP_EXCHANGE_MAX_KEY_SIZE) ||
-		(value_size > HV_KVP_EXCHANGE_MAX_VALUE_SIZE))
+		(value_size > HV_KVP_EXCHANGE_MAX_VALUE_SIZE)) {
+		syslog(LOG_ERR, "Got a too long key or value: key=%s, val=%s",
+		       key, value);
+
+		if (debug_enabled)
+			syslog(LOG_DEBUG, "[%s]:[%s]: Got a too long key or value: pool=%d, key=%s, val=%s",
+			       tm_str, __func__, pool, key, value);
 		return 1;
+	}
 
 	/*
 	 * First update the in-memory state.
@@ -348,6 +393,9 @@ static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,
 		 */
 		memcpy(record[i].value, value, value_size);
 		kvp_update_file(pool);
+		if (debug_enabled)
+			syslog(LOG_DEBUG, "[%s]:%s: updated: pool=%d key=%s val=%s",
+			       tm_str, __func__, pool, key, value);
 		return 0;
 	}
 
@@ -359,8 +407,10 @@ static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,
 		record = realloc(record, sizeof(struct kvp_record) *
 			 ENTRIES_PER_BLOCK * (num_blocks + 1));
 
-		if (record == NULL)
+		if (!record) {
+			syslog(LOG_ERR, "%s: Memory alloc failure", __func__);
 			return 1;
+		}
 		kvp_file_info[pool].num_blocks++;
 
 	}
@@ -368,6 +418,11 @@ static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,
 	memcpy(record[i].key, key, key_size);
 	kvp_file_info[pool].records = record;
 	kvp_file_info[pool].num_records++;
+
+	if (debug_enabled)
+		syslog(LOG_DEBUG, "[%s]:%s: added: pool=%d key=%s val=%s",
+		       tm_str, __func__, pool, key, value);
+
 	kvp_update_file(pool);
 	return 0;
 }
@@ -1662,6 +1717,7 @@ void print_usage(char *argv[])
 	fprintf(stderr, "Usage: %s [options]\n"
 		"Options are:\n"
 		"  -n, --no-daemon        stay in foreground, don't daemonize\n"
+		"  -d, --debug-enabled    Enable debug logs(syslog debug by default)\n"
 		"  -h, --help             print this help\n", argv[0]);
 }
 
@@ -1681,12 +1737,13 @@ int main(int argc, char *argv[])
 	int daemonize = 1, long_index = 0, opt;
 
 	static struct option long_options[] = {
-		{"help",	no_argument,	   0,  'h' },
-		{"no-daemon",	no_argument,	   0,  'n' },
-		{0,		0,		   0,  0   }
+		{"help",		no_argument,	   0,  'h' },
+		{"no-daemon",		no_argument,	   0,  'n' },
+		{"debug-enabled",	no_argument,	   0,  'd' },
+		{0,			0,		   0,  0   }
 	};
 
-	while ((opt = getopt_long(argc, argv, "hn", long_options,
+	while ((opt = getopt_long(argc, argv, "hnd", long_options,
 				  &long_index)) != -1) {
 		switch (opt) {
 		case 'n':
@@ -1695,6 +1752,9 @@ int main(int argc, char *argv[])
 		case 'h':
 			print_usage(argv);
 			exit(0);
+		case 'd':
+			debug_enabled = 1;
+			break;
 		default:
 			print_usage(argv);
 			exit(EXIT_FAILURE);
@@ -1717,6 +1777,9 @@ int main(int argc, char *argv[])
 	 */
 	kvp_get_domain_name(full_domain_name, sizeof(full_domain_name));
 
+	if (debug_enabled)
+		syslog(LOG_INFO, "Logging debug info in syslog(debug)");
+
 	if (kvp_file_init()) {
 		syslog(LOG_ERR, "Failed to initialize the pools");
 		exit(EXIT_FAILURE);
-- 
2.34.1

RE: [PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[Dexuan Cui]

> From: Shradha Gupta <shradhagupta@linux.microsoft.com>
> Sent: Sunday, March 30, 2025 11:15 PM
> [...]
> +static void convert_tm_to_string(char *tm_str, size_t tm_str_size)
> +{
> +	struct tm tm;
> +	time_t t;
> +
> +	time(&t);
> +	gmtime_r(&t, &tm);
> +	strftime(tm_str, tm_str_size, "%Y-%m-%dT%H:%M:%S", &tm);
> +}

Now the function is unnecessary since v2 uses syslog(), which already prefixes every
message with a timestamp.

> +static void kvp_dump_initial_pools(int pool)
> +{
> +	char tm_str[50];
> +	int i;
> +
> +	convert_tm_to_string(tm_str, sizeof(tm_str));
This is unnecessary now.

> +	syslog(LOG_DEBUG, "===Start dumping the contents of pool %d
> ===\n",
> +	       pool);
> +
> +	for (i = 0; i < kvp_file_info[pool].num_records; i++)
> +		syslog(LOG_DEBUG, "[%s]: pool: %d, %d/%d key=%s
> val=%s\n",
> +		       tm_str, pool, i, kvp_file_info[pool].num_records,

Can you change the 'i' to 'i+1'? This makes the messages a little more natural to
users who are not programmers :-)

>  static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,

Can you add a log message for KVP_OP_DELETE as well?

Thanks,
Dexuan

Re: [PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[Shradha Gupta]

On Mon, Mar 31, 2025 at 11:20:09PM +0000, Dexuan Cui wrote:
> > From: Shradha Gupta <shradhagupta@linux.microsoft.com>
> > Sent: Sunday, March 30, 2025 11:15 PM
> > [...]
> > +static void convert_tm_to_string(char *tm_str, size_t tm_str_size)
> > +{
> > +	struct tm tm;
> > +	time_t t;
> > +
> > +	time(&t);
> > +	gmtime_r(&t, &tm);
> > +	strftime(tm_str, tm_str_size, "%Y-%m-%dT%H:%M:%S", &tm);
> > +}
> 
> Now the function is unnecessary since v2 uses syslog(), which already prefixes every
> message with a timestamp.

Hi Dexuan,
I have deliberately kept this timestamp in the raw message so that
if/whenever they are redirected to other file, irrespective of the
configuration of the syslog we have valid timestamp for debugging
> 
> > +static void kvp_dump_initial_pools(int pool)
> > +{
> > +	char tm_str[50];
> > +	int i;
> > +
> > +	convert_tm_to_string(tm_str, sizeof(tm_str));
> This is unnecessary now.
> 
> > +	syslog(LOG_DEBUG, "===Start dumping the contents of pool %d
> > ===\n",
> > +	       pool);
> > +
> > +	for (i = 0; i < kvp_file_info[pool].num_records; i++)
> > +		syslog(LOG_DEBUG, "[%s]: pool: %d, %d/%d key=%s
> > val=%s\n",
> > +		       tm_str, pool, i, kvp_file_info[pool].num_records,
> 
> Can you change the 'i' to 'i+1'? This makes the messages a little more natural to
> users who are not programmers :-)
sure, but I am just worried that might cause confusion when someone
tried to co-relate it with the actual kv_pool_{i} contents that start
with 0.
> 
> >  static int kvp_key_add_or_modify(int pool, const __u8 *key, int key_size,
> 
> Can you add a log message for KVP_OP_DELETE as well?
sure, I can add this.
> 
> Thanks,
> Dexuan

RE: [PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[Dexuan Cui]

> From: Shradha Gupta <shradhagupta@linux.microsoft.com>
> Sent: Monday, March 31, 2025 9:06 PM
> > > +static void convert_tm_to_string(char *tm_str, size_t tm_str_size)
> > > +{
> > > +	struct tm tm;
> > > +	time_t t;
> > > +
> > > +	time(&t);
> > > +	gmtime_r(&t, &tm);
> > > +	strftime(tm_str, tm_str_size, "%Y-%m-%dT%H:%M:%S", &tm);
> > > +}
> >
> > Now the function is unnecessary since v2 uses syslog(), which already
> > prefixes every message with a timestamp.
> 
> Hi Dexuan,
> I have deliberately kept this timestamp in the raw message so that
> if/whenever they are redirected to other file, irrespective of the
> configuration of the syslog we have valid timestamp for debugging

A message produced by syslog() is always prefixed with a timestamp,
and IMO can't be redirected.  By "redirected to other file",  I guess
you mean systemd's options StandardOutput= and StandardError=
for a service, but those are stdout/err, not syslog().

> > > +static void kvp_dump_initial_pools(int pool)
> > > + [...]
> > > +	for (i = 0; i < kvp_file_info[pool].num_records; i++)
> > > +		syslog(LOG_DEBUG, "[%s]: pool: %d, %d/%d key=%s
> > > val=%s\n",
> > > +		       tm_str, pool, i, kvp_file_info[pool].num_records,
> >
> > Can you change the 'i' to 'i+1'? This makes the messages a little more
> > natural to users who are not programmers :-)
> sure, but I am just worried that might cause confusion when someone
> tried to co-relate it with the actual kv_pool_{i} contents that start
> with 0.
IMO these messages are mostly for admins, who would feel more
natural when seeing N/N as the last element, compared  with N-1/N.

Thanks,
Dexuan

Re: [PATCH v2] hv/hv_kvp_daemon: Enable debug logs for hv_kvp_daemon

[Shradha Gupta]

On Tue, Apr 01, 2025 at 07:18:04PM +0000, Dexuan Cui wrote:
> > From: Shradha Gupta <shradhagupta@linux.microsoft.com>
> > Sent: Monday, March 31, 2025 9:06 PM
> > > > +static void convert_tm_to_string(char *tm_str, size_t tm_str_size)
> > > > +{
> > > > +	struct tm tm;
> > > > +	time_t t;
> > > > +
> > > > +	time(&t);
> > > > +	gmtime_r(&t, &tm);
> > > > +	strftime(tm_str, tm_str_size, "%Y-%m-%dT%H:%M:%S", &tm);
> > > > +}
> > >
> > > Now the function is unnecessary since v2 uses syslog(), which already
> > > prefixes every message with a timestamp.
> > 
> > Hi Dexuan,
> > I have deliberately kept this timestamp in the raw message so that
> > if/whenever they are redirected to other file, irrespective of the
> > configuration of the syslog we have valid timestamp for debugging
> 
> A message produced by syslog() is always prefixed with a timestamp,
> and IMO can't be redirected.  By "redirected to other file",  I guess
> you mean systemd's options StandardOutput= and StandardError=
> for a service, but those are stdout/err, not syslog().

rsyslog can be configured to forward syslog logs from a service to a file.
If the timestamp template in rsyslog.conf is not configured, the timestamps
would be missed in forwarded file.
But I think that would be an issue to be handled by the script/service
forwarding these logs. It can be easily fixed by adding the timestamp
template.

I will remove the timestamp from the raw log message then. Thanks

> 
> > > > +static void kvp_dump_initial_pools(int pool)
> > > > + [...]
> > > > +	for (i = 0; i < kvp_file_info[pool].num_records; i++)
> > > > +		syslog(LOG_DEBUG, "[%s]: pool: %d, %d/%d key=%s
> > > > val=%s\n",
> > > > +		       tm_str, pool, i, kvp_file_info[pool].num_records,
> > >
> > > Can you change the 'i' to 'i+1'? This makes the messages a little more
> > > natural to users who are not programmers :-)
> > sure, but I am just worried that might cause confusion when someone
> > tried to co-relate it with the actual kv_pool_{i} contents that start
> > with 0.
> IMO these messages are mostly for admins, who would feel more
> natural when seeing N/N as the last element, compared  with N-1/N.
Got it, will modify this too
> 
> Thanks,
> Dexuan