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

[PATCH] 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 /var/log/kvp_debug_file.log. This information comes
in handy for debugging issues where the key-value pairs for certain
pools show mismatch/incorrect values.

Signed-off-by: Shradha Gupta <shradhagupta@linux.microsoft.com>
---
 tools/hv/hv_kvp_daemon.c | 120 ++++++++++++++++++++++++++++++++++++---
 1 file changed, 112 insertions(+), 8 deletions(-)

diff --git a/tools/hv/hv_kvp_daemon.c b/tools/hv/hv_kvp_daemon.c
index 04ba035d67e9..1f8b02b17356 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 = "";
@@ -91,6 +93,7 @@ static char *processor_arch;
 static char *os_build;
 static char *os_version;
 static char *lic_version = "Unknown version";
+static char debug_file[PATH_MAX];
 static char full_domain_name[HV_KVP_EXCHANGE_MAX_VALUE_SIZE];
 static struct utsname uts_buf;
 
@@ -99,6 +102,7 @@ static struct utsname uts_buf;
  */
 
 #define KVP_CONFIG_LOC	"/var/lib/hyperv"
+#define KVP_DEBUG_LOC	"/var/log/"
 
 #ifndef KVP_SCRIPTS_PATH
 #define KVP_SCRIPTS_PATH "/usr/libexec/hypervkvpd/"
@@ -153,6 +157,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 +197,45 @@ static void kvp_update_file(int pool)
 	kvp_release_lock(pool);
 }
 
+static void kvp_dump_initial_pools(int pool)
+{
+	FILE *debug_filep;
+	char tm_str[50];
+	int i, ret;
+
+	convert_tm_to_string(tm_str, sizeof(tm_str));
+
+	debug_filep = fopen(debug_file, "a");
+	if (!debug_filep) {
+		syslog(LOG_ERR, "Failed to open file: %s, pool: %d; error: %d%s",
+		       debug_file, pool, errno, strerror(errno));
+		return;
+	}
+
+	ret = fprintf(debug_filep, "===Start dumping the contents on pool %d ===\n",
+		      pool);
+	if (ret <= 0) {
+		syslog(LOG_ERR, "Failed to write to kvp debug file: %d", pool);
+		fclose(debug_filep);
+		return;
+	}
+
+	for (i = 0; i < kvp_file_info[pool].num_records; i++) {
+		ret = fprintf(debug_filep, "[%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);
+
+		if (ret <= 0) {
+			syslog(LOG_ERR, "Failed to write to kvp debug file: pool=%d, i=%u/%u",
+			       pool, i, kvp_file_info[pool].num_records);
+			break;
+		}
+	}
+
+	fclose(debug_filep);
+}
+
 static void kvp_update_mem_state(int pool)
 {
 	FILE *filep;
@@ -270,6 +323,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 +376,37 @@ 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;
+	FILE *filep = NULL;
+	int num_records;
+	char tm_str[50];
 	int num_blocks;
+	int i;
+
+	if (debug_enabled) {
+		filep = fopen(debug_file, "a");
+		if (!filep) {
+			syslog(LOG_ERR, "Failed to open file %s; error: %d",
+			       debug_file, errno);
+		} else {
+			convert_tm_to_string(tm_str, sizeof(tm_str));
+			fprintf(filep, "[%s]:%s: got a KVP: pool=%d key=%s val=%s\n",
+				__func__, tm_str, 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 (filep) {
+			fprintf(filep, "[%s]: Got a too long key or value: pool=%d, key=%s, val=%s\n",
+				tm_str, pool, key, value);
+			fclose(filep);
+		}
 		return 1;
+	}
 
 	/*
 	 * First update the in-memory state.
@@ -348,6 +426,11 @@ 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 (filep) {
+			fprintf(filep, "[%s]:%s: updated: pool=%d key=%s val=%s\n",
+				__func__, tm_str, pool, key, value);
+			fclose(filep);
+		}
 		return 0;
 	}
 
@@ -359,8 +442,12 @@ 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) {
+			if (filep)
+				fclose(filep);
+			syslog(LOG_ERR, "%s: Memory alloc failure", __func__);
 			return 1;
+		}
 		kvp_file_info[pool].num_blocks++;
 
 	}
@@ -368,6 +455,12 @@ 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 (filep) {
+		fprintf(filep, "[%s]:%s: added: pool=%d key=%s val=%s\n",
+			__func__, tm_str, pool, key, value);
+		fclose(filep);
+	}
 	kvp_update_file(pool);
 	return 0;
 }
@@ -1662,6 +1755,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\n"
 		"  -h, --help             print this help\n", argv[0]);
 }
 
@@ -1681,12 +1775,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 +1790,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 +1815,12 @@ int main(int argc, char *argv[])
 	 */
 	kvp_get_domain_name(full_domain_name, sizeof(full_domain_name));
 
+	if (debug_enabled) {
+		sprintf(debug_file, "%s%s", KVP_DEBUG_LOC, "kvp_debug_file.log");
+		syslog(LOG_INFO, "Logging debug info in kvp_debug_file=%s",
+		       debug_file);
+	}
+
 	if (kvp_file_init()) {
 		syslog(LOG_ERR, "Failed to initialize the pools");
 		exit(EXIT_FAILURE);
-- 
2.34.1

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

[Wei Liu]

On Mon, Mar 24, 2025 at 12:14:52AM -0700, Shradha Gupta wrote:
> 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 /var/log/kvp_debug_file.log. This information comes
> in handy for debugging issues where the key-value pairs for certain
> pools show mismatch/incorrect values.
> 
> Signed-off-by: Shradha Gupta <shradhagupta@linux.microsoft.com>

If debug is enabled, you can just open the file once during
initialization and close it when the daemon exits.

If you worry whether the log lines are written, you can use fflush(3) to
flush the buffer to the file every time you write to it, or use
setvbuf(3) to disable buffering.

> ---
>  tools/hv/hv_kvp_daemon.c | 120 ++++++++++++++++++++++++++++++++++++---
>  1 file changed, 112 insertions(+), 8 deletions(-)
> 
> diff --git a/tools/hv/hv_kvp_daemon.c b/tools/hv/hv_kvp_daemon.c
> index 04ba035d67e9..1f8b02b17356 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 = "";
> @@ -91,6 +93,7 @@ static char *processor_arch;
>  static char *os_build;
>  static char *os_version;
>  static char *lic_version = "Unknown version";
> +static char debug_file[PATH_MAX];
>  static char full_domain_name[HV_KVP_EXCHANGE_MAX_VALUE_SIZE];
>  static struct utsname uts_buf;
>  
> @@ -99,6 +102,7 @@ static struct utsname uts_buf;
>   */
>  
>  #define KVP_CONFIG_LOC	"/var/lib/hyperv"
> +#define KVP_DEBUG_LOC	"/var/log/"
>  
>  #ifndef KVP_SCRIPTS_PATH
>  #define KVP_SCRIPTS_PATH "/usr/libexec/hypervkvpd/"
> @@ -153,6 +157,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 +197,45 @@ static void kvp_update_file(int pool)
>  	kvp_release_lock(pool);
>  }
>  
> +static void kvp_dump_initial_pools(int pool)
> +{
> +	FILE *debug_filep;
> +	char tm_str[50];
> +	int i, ret;
> +
> +	convert_tm_to_string(tm_str, sizeof(tm_str));
> +
> +	debug_filep = fopen(debug_file, "a");
> +	if (!debug_filep) {
> +		syslog(LOG_ERR, "Failed to open file: %s, pool: %d; error: %d%s",
> +		       debug_file, pool, errno, strerror(errno));
> +		return;
> +	}
> +
> +	ret = fprintf(debug_filep, "===Start dumping the contents on pool %d ===\n",
> +		      pool);
> +	if (ret <= 0) {
> +		syslog(LOG_ERR, "Failed to write to kvp debug file: %d", pool);
> +		fclose(debug_filep);
> +		return;
> +	}
> +
> +	for (i = 0; i < kvp_file_info[pool].num_records; i++) {
> +		ret = fprintf(debug_filep, "[%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);
> +
> +		if (ret <= 0) {
> +			syslog(LOG_ERR, "Failed to write to kvp debug file: pool=%d, i=%u/%u",
> +			       pool, i, kvp_file_info[pool].num_records);
> +			break;
> +		}
> +	}
> +
> +	fclose(debug_filep);
> +}
> +
>  static void kvp_update_mem_state(int pool)
>  {
>  	FILE *filep;
> @@ -270,6 +323,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 +376,37 @@ 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;
> +	FILE *filep = NULL;
> +	int num_records;
> +	char tm_str[50];
>  	int num_blocks;
> +	int i;
> +
> +	if (debug_enabled) {
> +		filep = fopen(debug_file, "a");
> +		if (!filep) {
> +			syslog(LOG_ERR, "Failed to open file %s; error: %d",
> +			       debug_file, errno);
> +		} else {
> +			convert_tm_to_string(tm_str, sizeof(tm_str));
> +			fprintf(filep, "[%s]:%s: got a KVP: pool=%d key=%s val=%s\n",
> +				__func__, tm_str, 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 (filep) {
> +			fprintf(filep, "[%s]: Got a too long key or value: pool=%d, key=%s, val=%s\n",
> +				tm_str, pool, key, value);
> +			fclose(filep);
> +		}
>  		return 1;
> +	}
>  
>  	/*
>  	 * First update the in-memory state.
> @@ -348,6 +426,11 @@ 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 (filep) {
> +			fprintf(filep, "[%s]:%s: updated: pool=%d key=%s val=%s\n",
> +				__func__, tm_str, pool, key, value);
> +			fclose(filep);
> +		}
>  		return 0;
>  	}
>  
> @@ -359,8 +442,12 @@ 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) {
> +			if (filep)
> +				fclose(filep);
> +			syslog(LOG_ERR, "%s: Memory alloc failure", __func__);
>  			return 1;
> +		}
>  		kvp_file_info[pool].num_blocks++;
>  
>  	}
> @@ -368,6 +455,12 @@ 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 (filep) {
> +		fprintf(filep, "[%s]:%s: added: pool=%d key=%s val=%s\n",
> +			__func__, tm_str, pool, key, value);
> +		fclose(filep);
> +	}
>  	kvp_update_file(pool);
>  	return 0;
>  }
> @@ -1662,6 +1755,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\n"

You should specify where the log is written to. The only place that
tells where it is written to is in syslog.

Does systemd has a way to collect logs from a specific daemon? If so,
we can consider using that facility

Thanks,
Wei.

>  		"  -h, --help             print this help\n", argv[0]);
>  }
>  
> @@ -1681,12 +1775,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 +1790,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 +1815,12 @@ int main(int argc, char *argv[])
>  	 */
>  	kvp_get_domain_name(full_domain_name, sizeof(full_domain_name));
>  
> +	if (debug_enabled) {
> +		sprintf(debug_file, "%s%s", KVP_DEBUG_LOC, "kvp_debug_file.log");
> +		syslog(LOG_INFO, "Logging debug info in kvp_debug_file=%s",
> +		       debug_file);
> +	}
> +
>  	if (kvp_file_init()) {
>  		syslog(LOG_ERR, "Failed to initialize the pools");
>  		exit(EXIT_FAILURE);
> -- 
> 2.34.1
> 

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

[Shradha Gupta]

On Mon, Mar 24, 2025 at 04:57:29PM +0000, Wei Liu wrote:
> On Mon, Mar 24, 2025 at 12:14:52AM -0700, Shradha Gupta wrote:
> > 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 /var/log/kvp_debug_file.log. This information comes
> > in handy for debugging issues where the key-value pairs for certain
> > pools show mismatch/incorrect values.
> > 
> > Signed-off-by: Shradha Gupta <shradhagupta@linux.microsoft.com>
> 
> If debug is enabled, you can just open the file once during
> initialization and close it when the daemon exits.
> 
> If you worry whether the log lines are written, you can use fflush(3) to
> flush the buffer to the file every time you write to it, or use
> setvbuf(3) to disable buffering.
>
sure, that makes sense. I'll make that change 
> > ---
> >  tools/hv/hv_kvp_daemon.c | 120 ++++++++++++++++++++++++++++++++++++---
> >  1 file changed, 112 insertions(+), 8 deletions(-)
> > 
> > diff --git a/tools/hv/hv_kvp_daemon.c b/tools/hv/hv_kvp_daemon.c
> > index 04ba035d67e9..1f8b02b17356 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 = "";
> > @@ -91,6 +93,7 @@ static char *processor_arch;
> >  static char *os_build;
> >  static char *os_version;
> >  static char *lic_version = "Unknown version";
> > +static char debug_file[PATH_MAX];
> >  static char full_domain_name[HV_KVP_EXCHANGE_MAX_VALUE_SIZE];
> >  static struct utsname uts_buf;
> >  
> > @@ -99,6 +102,7 @@ static struct utsname uts_buf;
> >   */
> >  
> >  #define KVP_CONFIG_LOC	"/var/lib/hyperv"
> > +#define KVP_DEBUG_LOC	"/var/log/"
> >  
> >  #ifndef KVP_SCRIPTS_PATH
> >  #define KVP_SCRIPTS_PATH "/usr/libexec/hypervkvpd/"
> > @@ -153,6 +157,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 +197,45 @@ static void kvp_update_file(int pool)
> >  	kvp_release_lock(pool);
> >  }
> >  
> > +static void kvp_dump_initial_pools(int pool)
> > +{
> > +	FILE *debug_filep;
> > +	char tm_str[50];
> > +	int i, ret;
> > +
> > +	convert_tm_to_string(tm_str, sizeof(tm_str));
> > +
> > +	debug_filep = fopen(debug_file, "a");
> > +	if (!debug_filep) {
> > +		syslog(LOG_ERR, "Failed to open file: %s, pool: %d; error: %d%s",
> > +		       debug_file, pool, errno, strerror(errno));
> > +		return;
> > +	}
> > +
> > +	ret = fprintf(debug_filep, "===Start dumping the contents on pool %d ===\n",
> > +		      pool);
> > +	if (ret <= 0) {
> > +		syslog(LOG_ERR, "Failed to write to kvp debug file: %d", pool);
> > +		fclose(debug_filep);
> > +		return;
> > +	}
> > +
> > +	for (i = 0; i < kvp_file_info[pool].num_records; i++) {
> > +		ret = fprintf(debug_filep, "[%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);
> > +
> > +		if (ret <= 0) {
> > +			syslog(LOG_ERR, "Failed to write to kvp debug file: pool=%d, i=%u/%u",
> > +			       pool, i, kvp_file_info[pool].num_records);
> > +			break;
> > +		}
> > +	}
> > +
> > +	fclose(debug_filep);
> > +}
> > +
> >  static void kvp_update_mem_state(int pool)
> >  {
> >  	FILE *filep;
> > @@ -270,6 +323,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 +376,37 @@ 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;
> > +	FILE *filep = NULL;
> > +	int num_records;
> > +	char tm_str[50];
> >  	int num_blocks;
> > +	int i;
> > +
> > +	if (debug_enabled) {
> > +		filep = fopen(debug_file, "a");
> > +		if (!filep) {
> > +			syslog(LOG_ERR, "Failed to open file %s; error: %d",
> > +			       debug_file, errno);
> > +		} else {
> > +			convert_tm_to_string(tm_str, sizeof(tm_str));
> > +			fprintf(filep, "[%s]:%s: got a KVP: pool=%d key=%s val=%s\n",
> > +				__func__, tm_str, 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 (filep) {
> > +			fprintf(filep, "[%s]: Got a too long key or value: pool=%d, key=%s, val=%s\n",
> > +				tm_str, pool, key, value);
> > +			fclose(filep);
> > +		}
> >  		return 1;
> > +	}
> >  
> >  	/*
> >  	 * First update the in-memory state.
> > @@ -348,6 +426,11 @@ 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 (filep) {
> > +			fprintf(filep, "[%s]:%s: updated: pool=%d key=%s val=%s\n",
> > +				__func__, tm_str, pool, key, value);
> > +			fclose(filep);
> > +		}
> >  		return 0;
> >  	}
> >  
> > @@ -359,8 +442,12 @@ 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) {
> > +			if (filep)
> > +				fclose(filep);
> > +			syslog(LOG_ERR, "%s: Memory alloc failure", __func__);
> >  			return 1;
> > +		}
> >  		kvp_file_info[pool].num_blocks++;
> >  
> >  	}
> > @@ -368,6 +455,12 @@ 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 (filep) {
> > +		fprintf(filep, "[%s]:%s: added: pool=%d key=%s val=%s\n",
> > +			__func__, tm_str, pool, key, value);
> > +		fclose(filep);
> > +	}
> >  	kvp_update_file(pool);
> >  	return 0;
> >  }
> > @@ -1662,6 +1755,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\n"
> 
> You should specify where the log is written to. The only place that
> tells where it is written to is in syslog.
>
I can add the log location here as well, thanks.
 
> Does systemd has a way to collect logs from a specific daemon? If so,
> we can consider using that facility

yeah, using services that can be done. For hv_kvp_daemon, the services
are defined and configured by distro vendors(ex:
rhel:-hypervkvpd.service, ubuntu:-hv-kvp-daemon.service). Using
StandardOutput, StandardError directives(for these services), these logs
can be configured to be visible in journalctl logs as well.

Thanks,
Shradha
> 
> Thanks,
> Wei.
> 
> >  		"  -h, --help             print this help\n", argv[0]);
> >  }
> >  
> > @@ -1681,12 +1775,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 +1790,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 +1815,12 @@ int main(int argc, char *argv[])
> >  	 */
> >  	kvp_get_domain_name(full_domain_name, sizeof(full_domain_name));
> >  
> > +	if (debug_enabled) {
> > +		sprintf(debug_file, "%s%s", KVP_DEBUG_LOC, "kvp_debug_file.log");
> > +		syslog(LOG_INFO, "Logging debug info in kvp_debug_file=%s",
> > +		       debug_file);
> > +	}
> > +
> >  	if (kvp_file_init()) {
> >  		syslog(LOG_ERR, "Failed to initialize the pools");
> >  		exit(EXIT_FAILURE);
> > -- 
> > 2.34.1
> > 

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

[Wei Liu]

On Mon, Mar 24, 2025 at 11:24:08PM -0700, Shradha Gupta wrote:
[...]
> > > @@ -1662,6 +1755,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\n"
> > 
> > You should specify where the log is written to. The only place that
> > tells where it is written to is in syslog.
> >
> I can add the log location here as well, thanks.
>  
> > Does systemd has a way to collect logs from a specific daemon? If so,
> > we can consider using that facility
> 
> yeah, using services that can be done. For hv_kvp_daemon, the services
> are defined and configured by distro vendors(ex:
> rhel:-hypervkvpd.service, ubuntu:-hv-kvp-daemon.service). Using
> StandardOutput, StandardError directives(for these services), these logs
> can be configured to be visible in journalctl logs as well.

Yes, I would rather use systemd's logging facility. That simplifies this
patch. You won't need to handle a log file yourself.

Thanks,
Wei.

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

[Shradha Gupta]

On Tue, Mar 25, 2025 at 03:14:56PM +0000, Wei Liu wrote:
> On Mon, Mar 24, 2025 at 11:24:08PM -0700, Shradha Gupta wrote:
> [...]
> > > > @@ -1662,6 +1755,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\n"
> > > 
> > > You should specify where the log is written to. The only place that
> > > tells where it is written to is in syslog.
> > >
> > I can add the log location here as well, thanks.
> >  
> > > Does systemd has a way to collect logs from a specific daemon? If so,
> > > we can consider using that facility
> > 
> > yeah, using services that can be done. For hv_kvp_daemon, the services
> > are defined and configured by distro vendors(ex:
> > rhel:-hypervkvpd.service, ubuntu:-hv-kvp-daemon.service). Using
> > StandardOutput, StandardError directives(for these services), these logs
> > can be configured to be visible in journalctl logs as well.
> 
> Yes, I would rather use systemd's logging facility. That simplifies this
> patch. You won't need to handle a log file yourself.
> 
> Thanks,
> Wei.
Thanks Wei. Summarizing the changes in next version, I will skip the log
file and add debug log in syslog as LOG_DEBUG. This would be enabled
with -d(debug-enabled) flag in the the daemon. The Distro vendors can
modify their service file configuration to redirect/view these logs
accordingly.