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 <shradhagu...@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
> >
