[PATCH RESEND kvmtool 0/4] Add --loglevel argument

[PATCH RESEND kvmtool 0/4] Add --loglevel argument

[Alexandru Elisei]

Forgot to add the mailing list the first time I sent the series, sorry for
that.

kvmtool can be unnecessarily verbose at times, and Will proposed in a chat
we had a while ago to add a --loglevel command line argument to choose
which type of messages to silence. This is me taking a stab at it.

Build tested for all arches and run tested lightly on a rockpro64 and my
x86 machine.

Base commit is 3b1cdcf9e78f ("virtio/vhost: Clear VIRTIO_F_ACCESS_PLATFORM").

Alexandru Elisei (4):
  util: Make pr_err() return void
  Replace printf/fprintf with pr_* macros
  util: Use __pr_debug() instead of pr_info() to print debug messages
  Add --loglevel argument for the run command

 arm/gic.c            |   5 +--
 builtin-run.c        | 100 ++++++++++++++++++++++++++++++++-----------
 builtin-setup.c      |  18 ++++----
 guest_compat.c       |   2 +-
 include/kvm/util.h   |  14 ++++--
 kvm-cpu.c            |  12 +++---
 mmio.c               |  10 ++---
 util/parse-options.c |  28 ++++++------
 util/util.c          |  27 +++++++++++-
 virtio/core.c        |   6 +--
 x86/ioport.c         |  11 +++--
 11 files changed, 157 insertions(+), 76 deletions(-)

-- 
2.41.0

[PATCH RESEND kvmtool 1/4] util: Make pr_err() return void

[Alexandru Elisei]

Of all the pr_* functions, pr_err() is the only function that returns a
value, which is -1. The code in parse_options is the only code that relies
on pr_err() returning a value, and that value must be exactly -1, because
it is being treated differently than the other return values.

This makes the code opaque, because it's not immediately obvious where that
value comes from, and fragile, as a change in the return value of pr_err
would break it.

Make pr_err() more like the other functions and don't return a value.

Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
---
 include/kvm/util.h   |  2 +-
 util/parse-options.c | 28 ++++++++++++++++------------
 util/util.c          |  3 +--
 3 files changed, 18 insertions(+), 15 deletions(-)

diff --git a/include/kvm/util.h b/include/kvm/util.h
index b49454876a83..f51f370d2b37 100644
--- a/include/kvm/util.h
+++ b/include/kvm/util.h
@@ -39,7 +39,7 @@ extern bool do_debug_print;
 
 extern void die(const char *err, ...) NORETURN __attribute__((format (printf, 1, 2)));
 extern void die_perror(const char *s) NORETURN;
-extern int pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
+extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
diff --git a/util/parse-options.c b/util/parse-options.c
index 9a1bbee6c271..fb44b48d14c8 100644
--- a/util/parse-options.c
+++ b/util/parse-options.c
@@ -17,10 +17,13 @@
 static int opterror(const struct option *opt, const char *reason, int flags)
 {
 	if (flags & OPT_SHORT)
-		return pr_err("switch `%c' %s", opt->short_name, reason);
-	if (flags & OPT_UNSET)
-		return pr_err("option `no-%s' %s", opt->long_name, reason);
-	return pr_err("option `%s' %s", opt->long_name, reason);
+		pr_err("switch `%c' %s", opt->short_name, reason);
+	else if (flags & OPT_UNSET)
+		pr_err("option `no-%s' %s", opt->long_name, reason);
+	else
+		pr_err("option `%s' %s", opt->long_name, reason);
+
+	return -1;
 }
 
 static int get_arg(struct parse_opt_ctx_t *p, const struct option *opt,
@@ -429,14 +432,15 @@ is_abbreviated:
 		return get_value(p, options, flags);
 	}
 
-	if (ambiguous_option)
-		return pr_err("Ambiguous option: %s "
-				"(could be --%s%s or --%s%s)",
-				arg,
-				(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
-				ambiguous_option->long_name,
-				(abbrev_flags & OPT_UNSET) ?  "no-" : "",
-				abbrev_option->long_name);
+	if (ambiguous_option) {
+		pr_err("Ambiguous option: %s " "(could be --%s%s or --%s%s)",
+			arg,
+			(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
+			ambiguous_option->long_name,
+			(abbrev_flags & OPT_UNSET) ?  "no-" : "",
+			abbrev_option->long_name);
+		return -1;
+	}
 	if (abbrev_option)
 		return get_value(p, abbrev_option, abbrev_flags);
 	return -2;
diff --git a/util/util.c b/util/util.c
index 1877105e3c08..f59f26e1581c 100644
--- a/util/util.c
+++ b/util/util.c
@@ -47,14 +47,13 @@ void die(const char *err, ...)
 	va_end(params);
 }
 
-int pr_err(const char *err, ...)
+void pr_err(const char *err, ...)
 {
 	va_list params;
 
 	va_start(params, err);
 	error_builtin(err, params);
 	va_end(params);
-	return -1;
 }
 
 void pr_warning(const char *warn, ...)
-- 
2.41.0

[PATCH RESEND kvmtool 2/4] Replace printf/fprintf with pr_* macros

[Alexandru Elisei]

To prepare for allowing finer control over the messages that kvmtool
displays, replace printf() and fprintf() with the pr_* macros.

Minor changes were made to fix coding style issues that were pet peeves for
the author. And use pr_err() in kvm_cpu__init() instead of pr_warning() for
fatal errors.

Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
---
I have my doubts about the change to kernel_usage_with_options(). I did
this way instead of replacing fprintf() with pr_err() because this is how
it would have looked like:

  Error: Could not find default kernel image in:
  Error: 	./bzImage
  Error: 	arch/arm64/boot/bzImage
  Error: 	../../arch/arm64/boot/bzImage
  Error: 	/boot/vmlinuz-6.4.0
  Error: 	/boot/bzImage-6.4.0

And this is how it looks now:

  Error: Could not find default kernel image in:
	./bzImage
	arch/arm64/boot/bzImage
	../../arch/arm64/boot/bzImage
	/boot/vmlinuz-6.4.0
	/boot/bzImage-6.4.0

That, and msg ends up being 5 * 4096 ~= 20k bytes in size.
Happy to come up with something else if this is not satisfactory.

 arm/gic.c       |  5 ++--
 builtin-run.c   | 68 ++++++++++++++++++++++++++++++++++---------------
 builtin-setup.c | 18 ++++++-------
 guest_compat.c  |  2 +-
 kvm-cpu.c       | 12 ++++-----
 mmio.c          | 10 ++++----
 virtio/core.c   |  6 ++---
 x86/ioport.c    | 11 ++++----
 8 files changed, 78 insertions(+), 54 deletions(-)

diff --git a/arm/gic.c b/arm/gic.c
index a223a72cfeb9..0795e9509bf8 100644
--- a/arm/gic.c
+++ b/arm/gic.c
@@ -115,9 +115,8 @@ static int gic__create_its_frame(struct kvm *kvm, u64 its_frame_addr)
 
 	err = ioctl(kvm->vm_fd, KVM_CREATE_DEVICE, &its_device);
 	if (err) {
-		fprintf(stderr,
-			"GICv3 ITS requested, but kernel does not support it.\n");
-		fprintf(stderr, "Try --irqchip=gicv3 instead\n");
+		pr_err("GICv3 ITS requested, but kernel does not support it.");
+		pr_err("Try --irqchip=gicv3 instead");
 		return err;
 	}
 
diff --git a/builtin-run.c b/builtin-run.c
index bd0d0b9c2467..79d031777c26 100644
--- a/builtin-run.c
+++ b/builtin-run.c
@@ -271,12 +271,14 @@ static void *kvm_cpu_thread(void *arg)
 	return (void *) (intptr_t) 0;
 
 panic_kvm:
-	fprintf(stderr, "KVM exit reason: %u (\"%s\")\n",
+	pr_err("KVM exit reason: %u (\"%s\")",
 		current_kvm_cpu->kvm_run->exit_reason,
 		kvm_exit_reasons[current_kvm_cpu->kvm_run->exit_reason]);
-	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN)
-		fprintf(stderr, "KVM exit code: 0x%llu\n",
+
+	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN) {
+		pr_err("KVM exit code: 0x%llu",
 			(unsigned long long)current_kvm_cpu->kvm_run->hw.hardware_exit_reason);
+	}
 
 	kvm_cpu__set_debug_fd(STDOUT_FILENO);
 	kvm_cpu__show_registers(current_kvm_cpu);
@@ -310,28 +312,53 @@ static const char *default_vmlinux[] = {
 
 static void kernel_usage_with_options(void)
 {
-	const char **k;
+	const char *prelude = "Could not find default kernel image in:";
 	struct utsname uts;
+	char *msg, *tmp;
+	size_t msg_size;
+	const char **k;
+
+	/* Ignore NULL path in host_kernels. */
+	msg_size = PATH_MAX * (ARRAY_SIZE(host_kernels) - 1);
+	msg_size += PATH_MAX * (ARRAY_SIZE(default_kernels) - 1);
+	msg = calloc(msg_size, 1);
+	if (!msg)
+		die_perror("calloc");
+	tmp = msg;
+
+	snprintf(tmp, msg_size, "%s\n", prelude);
+	msg_size -= strlen(prelude) + 1;
+	tmp += strlen(prelude) + 1;
 
-	fprintf(stderr, "Fatal: could not find default kernel image in:\n");
 	k = &default_kernels[0];
 	while (*k) {
-		fprintf(stderr, "\t%s\n", *k);
+		if (snprintf(tmp, msg_size, "\t%s\n", *k) < 0)
+			goto out;
+		msg_size -= strlen(*k) + 2;
+		tmp += strlen(*k) + 2;
 		k++;
 	}
 
 	if (uname(&uts) < 0)
-		return;
+		goto out;
 
 	k = &host_kernels[0];
 	while (*k) {
 		if (snprintf(kernel, PATH_MAX, "%s-%s", *k, uts.release) < 0)
-			return;
-		fprintf(stderr, "\t%s\n", kernel);
+			goto out;
+		if (snprintf(tmp, msg_size, "\t%s\n", kernel) < 0)
+			goto out;
+		msg_size -= strlen(kernel) + 2;
+		tmp += strlen(kernel) + 2;
 		k++;
 	}
-	fprintf(stderr, "\nPlease see '%s run --help' for more options.\n\n",
+out:
+	/* Remove trailing newline - pr_err() will add its own. */
+	msg[strlen(msg) - 1] = '\0';
+	pr_err("%s", msg);
+	pr_info("Please see '%s run --help' for more options.",
 		KVM_BINARY_NAME);
+	free(msg);
 }
 
 static u64 host_ram_size(void)
@@ -656,8 +683,7 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
 
 			if ((kvm_run_wrapper == KVM_RUN_DEFAULT && kvm->cfg.kernel_filename) ||
 				(kvm_run_wrapper == KVM_RUN_SANDBOX && kvm->cfg.sandbox)) {
-				fprintf(stderr, "Cannot handle parameter: "
-						"%s\n", argv[0]);
+				pr_err("Cannot handle parameter: %s", argv[0]);
 				usage_with_options(run_usage, options);
 				free(kvm);
 				return ERR_PTR(-EINVAL);
@@ -775,15 +801,15 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
 		kvm_run_set_real_cmdline(kvm);
 
 	if (kvm->cfg.kernel_filename) {
-		printf("  # %s run -k %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
-		       kvm->cfg.kernel_filename,
-		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
-		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
+		pr_info("# %s run -k %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
+			kvm->cfg.kernel_filename,
+			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
+			kvm->cfg.nrcpus, kvm->cfg.guest_name);
 	} else if (kvm->cfg.firmware_filename) {
-		printf("  # %s run --firmware %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
-		       kvm->cfg.firmware_filename,
-		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
-		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
+		pr_info("# %s run --firmware %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
+			kvm->cfg.firmware_filename,
+			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
+			kvm->cfg.nrcpus, kvm->cfg.guest_name);
 	}
 
 	if (init_list__init(kvm) < 0)
@@ -815,7 +841,7 @@ static void kvm_cmd_run_exit(struct kvm *kvm, int guest_ret)
 	init_list__exit(kvm);
 
 	if (guest_ret == 0)
-		printf("\n  # KVM session ended normally.\n");
+		pr_info("KVM session ended normally.");
 }
 
 int kvm_cmd_run(int argc, const char **argv, const char *prefix)
diff --git a/builtin-setup.c b/builtin-setup.c
index b24d2a18921e..c333ae064b21 100644
--- a/builtin-setup.c
+++ b/builtin-setup.c
@@ -271,15 +271,15 @@ int kvm_cmd_setup(int argc, const char **argv, const char *prefix)
 		kvm_setup_help();
 
 	r = do_setup(instance_name);
-	if (r == 0)
-		printf("A new rootfs '%s' has been created in '%s%s'.\n\n"
-			"You can now start it by running the following command:\n\n"
-			"  %s run -d %s\n",
-			instance_name, kvm__get_dir(), instance_name,
-			KVM_BINARY_NAME,instance_name);
-	else
-		printf("Unable to create rootfs in %s%s: %s\n",
-			kvm__get_dir(), instance_name, strerror(errno));
+	if (r == 0) {
+		pr_info("A new rootfs '%s' has been created in '%s%s'.",
+			instance_name, kvm__get_dir(), instance_name);
+		pr_info("You can now start it by running the following command:");
+		pr_info("%s run -d %s", KVM_BINARY_NAME, instance_name);
+	} else {
+		pr_err("Unable to create rootfs in %s%s: %s",
+		       kvm__get_dir(), instance_name, strerror(errno));
+	}
 
 	return r;
 }
diff --git a/guest_compat.c b/guest_compat.c
index fd4704b20b16..93f9aabcd6db 100644
--- a/guest_compat.c
+++ b/guest_compat.c
@@ -86,7 +86,7 @@ int compat__print_all_messages(void)
 
 		msg = list_first_entry(&messages, struct compat_message, list);
 
-		printf("\n  # KVM compatibility warning.\n\t%s\n\t%s\n",
+		pr_warning("KVM compatibility warning.\n\t%s\n\t%s",
 			msg->title, msg->desc);
 
 		list_del(&msg->list);
diff --git a/kvm-cpu.c b/kvm-cpu.c
index 7dec08894cd3..1c566b3f21d6 100644
--- a/kvm-cpu.c
+++ b/kvm-cpu.c
@@ -265,32 +265,32 @@ int kvm_cpu__init(struct kvm *kvm)
 	recommended_cpus = kvm__recommended_cpus(kvm);
 
 	if (kvm->cfg.nrcpus > max_cpus) {
-		printf("  # Limit the number of CPUs to %d\n", max_cpus);
+		pr_warning("Limiting the number of CPUs to %d", max_cpus);
 		kvm->cfg.nrcpus = max_cpus;
 	} else if (kvm->cfg.nrcpus > recommended_cpus) {
-		printf("  # Warning: The maximum recommended amount of VCPUs"
-			" is %d\n", recommended_cpus);
+		pr_warning("The maximum recommended amount of VCPUs is %d",
+			   recommended_cpus);
 	}
 
 	kvm->nrcpus = kvm->cfg.nrcpus;
 
 	task_eventfd = eventfd(0, 0);
 	if (task_eventfd < 0) {
-		pr_warning("Couldn't create task_eventfd");
+		pr_err("Couldn't create task_eventfd");
 		return task_eventfd;
 	}
 
 	/* Alloc one pointer too many, so array ends up 0-terminated */
 	kvm->cpus = calloc(kvm->nrcpus + 1, sizeof(void *));
 	if (!kvm->cpus) {
-		pr_warning("Couldn't allocate array for %d CPUs", kvm->nrcpus);
+		pr_err("Couldn't allocate array for %d CPUs", kvm->nrcpus);
 		return -ENOMEM;
 	}
 
 	for (i = 0; i < kvm->nrcpus; i++) {
 		kvm->cpus[i] = kvm_cpu__arch_init(kvm, i);
 		if (!kvm->cpus[i]) {
-			pr_warning("unable to initialize KVM VCPU");
+			pr_err("unable to initialize KVM VCPU");
 			goto fail_alloc;
 		}
 	}
diff --git a/mmio.c b/mmio.c
index 5a114e9997d9..d9a09565185c 100644
--- a/mmio.c
+++ b/mmio.c
@@ -203,9 +203,9 @@ bool kvm__emulate_mmio(struct kvm_cpu *vcpu, u64 phys_addr, u8 *data,
 	mmio = mmio_get(&mmio_tree, phys_addr, len);
 	if (!mmio) {
 		if (vcpu->kvm->cfg.mmio_debug)
-			fprintf(stderr,	"Warning: Ignoring MMIO %s at %016llx (length %u)\n",
-				to_direction(is_write),
-				(unsigned long long)phys_addr, len);
+			pr_warning("Warning: Ignoring MMIO %s at %016llx (length %u)",
+				   to_direction(is_write),
+				   (unsigned long long)phys_addr, len);
 		goto out;
 	}
 
@@ -225,8 +225,8 @@ bool kvm__emulate_io(struct kvm_cpu *vcpu, u16 port, void *data,
 	mmio = mmio_get(&pio_tree, port, size);
 	if (!mmio) {
 		if (vcpu->kvm->cfg.ioport_debug) {
-			fprintf(stderr, "IO error: %s port=%x, size=%d, count=%u\n",
-				to_direction(direction), port, size, count);
+			pr_warning("IO error: %s port=%x, size=%d, count=%u",
+				   to_direction(direction), port, size, count);
 
 			return false;
 		}
diff --git a/virtio/core.c b/virtio/core.c
index a77e23bc9b34..c4e79c7a3d40 100644
--- a/virtio/core.c
+++ b/virtio/core.c
@@ -417,10 +417,10 @@ int virtio_compat_add_message(const char *device, const char *config)
 		return -ENOMEM;
 	}
 
-	snprintf(title, len, "%s device was not detected.", device);
-	snprintf(desc,  len, "While you have requested a %s device, "
+	snprintf(title, len, "   %s device was not detected.", device);
+	snprintf(desc,  len, "   While you have requested a %s device, "
 			     "the guest kernel did not initialize it.\n"
-			     "\tPlease make sure that the guest kernel was "
+			     "\t   Please make sure that the guest kernel was "
 			     "compiled with %s=y enabled in .config.",
 			     device, config);
 
diff --git a/x86/ioport.c b/x86/ioport.c
index 06b7defbaae8..0f1a857483c1 100644
--- a/x86/ioport.c
+++ b/x86/ioport.c
@@ -14,9 +14,10 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
 	if (!vcpu->kvm->cfg.ioport_debug)
 		return;
 
-	fprintf(stderr, "debug port %s from VCPU%lu: port=0x%lx, size=%u",
-		is_write ? "write" : "read", vcpu->cpu_id,
-		(unsigned long)addr, len);
+	pr_debug("debug port %s from VCPU%lu: port=0x%lx, size=%u",
+		 is_write ? "write" : "read", vcpu->cpu_id,
+		 (unsigned long)addr, len);
+
 	if (is_write) {
 		u32 value;
 
@@ -26,9 +27,7 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
 		case 4: value = ioport__read32((u32*)data); break;
 		default: value = 0; break;
 		}
-		fprintf(stderr, ", data: 0x%x\n", value);
-	} else {
-		fprintf(stderr, "\n");
+		pr_debug("data: 0x%x", value);
 	}
 }
 
-- 
2.41.0

[PATCH RESEND kvmtool 3/4] util: Use __pr_debug() instead of pr_info() to print debug messages

[Alexandru Elisei]

pr_debug() is special, because it can be suppressed with a command line
argument, and because it needs to be a macro to capture the correct
filename, function name and line number. Display debug messages with the
prefix "Debug", to make it clear that those aren't informational messages.

Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
---
 include/kvm/util.h |  3 ++-
 util/util.c        | 15 +++++++++++++++
 2 files changed, 17 insertions(+), 1 deletion(-)

diff --git a/include/kvm/util.h b/include/kvm/util.h
index f51f370d2b37..6920ce2630ad 100644
--- a/include/kvm/util.h
+++ b/include/kvm/util.h
@@ -42,12 +42,13 @@ extern void die_perror(const char *s) NORETURN;
 extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
+extern void __pr_debug(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
 
 #define pr_debug(fmt, ...)						\
 	do {								\
 		if (do_debug_print)					\
-			pr_info("(%s) %s:%d: " fmt, __FILE__,		\
+			__pr_debug("(%s) %s:%d: " fmt, __FILE__,	\
 				__func__, __LINE__, ##__VA_ARGS__);	\
 	} while (0)
 
diff --git a/util/util.c b/util/util.c
index f59f26e1581c..e3b36f67f899 100644
--- a/util/util.c
+++ b/util/util.c
@@ -38,6 +38,11 @@ static void info_builtin(const char *info, va_list params)
 	report(" Info: ", info, params);
 }
 
+static void debug_builtin(const char *info, va_list params)
+{
+	report(" Debug: ", info, params);
+}
+
 void die(const char *err, ...)
 {
 	va_list params;
@@ -74,6 +79,16 @@ void pr_info(const char *info, ...)
 	va_end(params);
 }
 
+/* Do not call directly; call pr_debug() instead. */
+void __pr_debug(const char *info, ...)
+{
+	va_list params;
+
+	va_start(params, info);
+	debug_builtin(info, params);
+	va_end(params);
+}
+
 void die_perror(const char *s)
 {
 	perror(s);
-- 
2.41.0

[PATCH RESEND kvmtool 4/4] Add --loglevel argument for the run command

[Alexandru Elisei]

Add --loglevel command line argument, with the possible values of 'error',
'warning', 'info' or 'debug' to control what messages kvmtool displays. The
argument functions similarly to the Linux kernel parameter, when lower
verbosity levels hide all message with a higher verbosity (for example,
'warning' hides info and debug messages, allows warning and error
messsages).

The default level is 'info', to match the current behaviour. --debug has
been kept as a legacy option, which might be removed in the future.

Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
---
 builtin-run.c      | 32 ++++++++++++++++++++++++++++----
 include/kvm/util.h |  9 +++++++--
 util/util.c        |  9 +++++++++
 3 files changed, 44 insertions(+), 6 deletions(-)

diff --git a/builtin-run.c b/builtin-run.c
index 79d031777c26..2e4378819f00 100644
--- a/builtin-run.c
+++ b/builtin-run.c
@@ -58,8 +58,7 @@
 __thread struct kvm_cpu *current_kvm_cpu;
 
 static int  kvm_run_wrapper;
-
-bool do_debug_print = false;
+int loglevel = LOGLEVEL_INFO;
 
 static const char * const run_usage[] = {
 	"lkvm run [<options>] [<kernel image>]",
@@ -146,6 +145,27 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
 	return 0;
 }
 
+static int loglevel_parser(const struct option *opt, const char *arg, int unset)
+{
+	if (strcmp(opt->long_name, "debug") == 0) {
+		loglevel = LOGLEVEL_DEBUG;
+		return 0;
+	}
+
+	if (strcmp(arg, "debug") == 0)
+		loglevel = LOGLEVEL_DEBUG;
+	else if (strcmp(arg, "info") == 0)
+		loglevel = LOGLEVEL_INFO;
+	else if (strcmp(arg, "warning") == 0)
+		loglevel = LOGLEVEL_WARNING;
+	else if (strcmp(arg, "error") == 0)
+		loglevel = LOGLEVEL_ERROR;
+	else
+		die("Unknown loglevel: %s", arg);
+
+	return 0;
+}
+
 #ifndef OPT_ARCH_RUN
 #define OPT_ARCH_RUN(...)
 #endif
@@ -215,6 +235,8 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
 		     VIRTIO_TRANS_OPT_HELP_SHORT,		        \
 		     "Type of virtio transport",			\
 		     virtio_transport_parser, NULL),			\
+	OPT_CALLBACK('\0', "loglevel", NULL, "[error|warning|info|debug]",\
+			"Set the verbosity level", loglevel_parser, NULL),\
 									\
 	OPT_GROUP("Kernel options:"),					\
 	OPT_STRING('k', "kernel", &(cfg)->kernel_filename, "kernel",	\
@@ -241,8 +263,10 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
 		     vfio_device_parser, kvm),				\
 									\
 	OPT_GROUP("Debug options:"),					\
-	OPT_BOOLEAN('\0', "debug", &do_debug_print,			\
-			"Enable debug messages"),			\
+	OPT_CALLBACK_NOOPT('\0', "debug", kvm, NULL,			\
+			"Enable debug messages (deprecated, use "	\
+			"--loglevel=debug instead)",			\
+			loglevel_parser, NULL),				\
 	OPT_BOOLEAN('\0', "debug-single-step", &(cfg)->single_step,	\
 			"Enable single stepping"),			\
 	OPT_BOOLEAN('\0', "debug-ioport", &(cfg)->ioport_debug,		\
diff --git a/include/kvm/util.h b/include/kvm/util.h
index 6920ce2630ad..e9d63c184752 100644
--- a/include/kvm/util.h
+++ b/include/kvm/util.h
@@ -32,7 +32,10 @@
 #endif
 #endif
 
-extern bool do_debug_print;
+#define LOGLEVEL_ERROR		0
+#define LOGLEVEL_WARNING	1
+#define LOGLEVEL_INFO		2
+#define LOGLEVEL_DEBUG		3
 
 #define PROT_RW (PROT_READ|PROT_WRITE)
 #define MAP_ANON_NORESERVE (MAP_PRIVATE | MAP_ANONYMOUS | MAP_NORESERVE)
@@ -45,9 +48,11 @@ extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)))
 extern void __pr_debug(const char *err, ...) __attribute__((format (printf, 1, 2)));
 extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
 
+extern int loglevel;
+
 #define pr_debug(fmt, ...)						\
 	do {								\
-		if (do_debug_print)					\
+		if (loglevel >= LOGLEVEL_DEBUG)				\
 			__pr_debug("(%s) %s:%d: " fmt, __FILE__,	\
 				__func__, __LINE__, ##__VA_ARGS__);	\
 	} while (0)
diff --git a/util/util.c b/util/util.c
index e3b36f67f899..962e8d4edb21 100644
--- a/util/util.c
+++ b/util/util.c
@@ -56,6 +56,9 @@ void pr_err(const char *err, ...)
 {
 	va_list params;
 
+	if (loglevel < LOGLEVEL_ERROR)
+		return;
+
 	va_start(params, err);
 	error_builtin(err, params);
 	va_end(params);
@@ -65,6 +68,9 @@ void pr_warning(const char *warn, ...)
 {
 	va_list params;
 
+	if (loglevel < LOGLEVEL_WARNING)
+		return;
+
 	va_start(params, warn);
 	warn_builtin(warn, params);
 	va_end(params);
@@ -74,6 +80,9 @@ void pr_info(const char *info, ...)
 {
 	va_list params;
 
+	if (loglevel < LOGLEVEL_INFO)
+		return;
+
 	va_start(params, info);
 	info_builtin(info, params);
 	va_end(params);
-- 
2.41.0

Re: [PATCH RESEND kvmtool 1/4] util: Make pr_err() return void

[Jean-Philippe Brucker]

On Fri, Jun 30, 2023 at 02:31:31PM +0100, Alexandru Elisei wrote:
> Of all the pr_* functions, pr_err() is the only function that returns a
> value, which is -1. The code in parse_options is the only code that relies
> on pr_err() returning a value, and that value must be exactly -1, because
> it is being treated differently than the other return values.
> 
> This makes the code opaque, because it's not immediately obvious where that
> value comes from, and fragile, as a change in the return value of pr_err
> would break it.
> 
> Make pr_err() more like the other functions and don't return a value.
> 
> Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>

One small nit below, otherwise 

Reviewed-by: Jean-Philippe Brucker <jean-philippe@linaro.org>

> ---
>  include/kvm/util.h   |  2 +-
>  util/parse-options.c | 28 ++++++++++++++++------------
>  util/util.c          |  3 +--
>  3 files changed, 18 insertions(+), 15 deletions(-)
> 
> diff --git a/include/kvm/util.h b/include/kvm/util.h
> index b49454876a83..f51f370d2b37 100644
> --- a/include/kvm/util.h
> +++ b/include/kvm/util.h
> @@ -39,7 +39,7 @@ extern bool do_debug_print;
>  
>  extern void die(const char *err, ...) NORETURN __attribute__((format (printf, 1, 2)));
>  extern void die_perror(const char *s) NORETURN;
> -extern int pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
> +extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
> diff --git a/util/parse-options.c b/util/parse-options.c
> index 9a1bbee6c271..fb44b48d14c8 100644
> --- a/util/parse-options.c
> +++ b/util/parse-options.c
> @@ -17,10 +17,13 @@
>  static int opterror(const struct option *opt, const char *reason, int flags)
>  {
>  	if (flags & OPT_SHORT)
> -		return pr_err("switch `%c' %s", opt->short_name, reason);
> -	if (flags & OPT_UNSET)
> -		return pr_err("option `no-%s' %s", opt->long_name, reason);
> -	return pr_err("option `%s' %s", opt->long_name, reason);
> +		pr_err("switch `%c' %s", opt->short_name, reason);
> +	else if (flags & OPT_UNSET)
> +		pr_err("option `no-%s' %s", opt->long_name, reason);
> +	else
> +		pr_err("option `%s' %s", opt->long_name, reason);
> +
> +	return -1;
>  }
>  
>  static int get_arg(struct parse_opt_ctx_t *p, const struct option *opt,
> @@ -429,14 +432,15 @@ is_abbreviated:
>  		return get_value(p, options, flags);
>  	}
>  
> -	if (ambiguous_option)
> -		return pr_err("Ambiguous option: %s "
> -				"(could be --%s%s or --%s%s)",
> -				arg,
> -				(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
> -				ambiguous_option->long_name,
> -				(abbrev_flags & OPT_UNSET) ?  "no-" : "",
> -				abbrev_option->long_name);
> +	if (ambiguous_option) {
> +		pr_err("Ambiguous option: %s " "(could be --%s%s or --%s%s)",

drop " "

> +			arg,
> +			(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
> +			ambiguous_option->long_name,
> +			(abbrev_flags & OPT_UNSET) ?  "no-" : "",
> +			abbrev_option->long_name);
> +		return -1;
> +	}
>  	if (abbrev_option)
>  		return get_value(p, abbrev_option, abbrev_flags);
>  	return -2;
> diff --git a/util/util.c b/util/util.c
> index 1877105e3c08..f59f26e1581c 100644
> --- a/util/util.c
> +++ b/util/util.c
> @@ -47,14 +47,13 @@ void die(const char *err, ...)
>  	va_end(params);
>  }
>  
> -int pr_err(const char *err, ...)
> +void pr_err(const char *err, ...)
>  {
>  	va_list params;
>  
>  	va_start(params, err);
>  	error_builtin(err, params);
>  	va_end(params);
> -	return -1;
>  }
>  
>  void pr_warning(const char *warn, ...)
> -- 
> 2.41.0
> 

Re: [PATCH RESEND kvmtool 2/4] Replace printf/fprintf with pr_* macros

[Jean-Philippe Brucker]

On Fri, Jun 30, 2023 at 02:31:32PM +0100, Alexandru Elisei wrote:
> To prepare for allowing finer control over the messages that kvmtool
> displays, replace printf() and fprintf() with the pr_* macros.
> 
> Minor changes were made to fix coding style issues that were pet peeves for
> the author. And use pr_err() in kvm_cpu__init() instead of pr_warning() for
> fatal errors.
> 
> Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>

Looks good, some small things below

> ---
> I have my doubts about the change to kernel_usage_with_options(). I did
> this way instead of replacing fprintf() with pr_err() because this is how
> it would have looked like:
> 
>   Error: Could not find default kernel image in:
>   Error: 	./bzImage
>   Error: 	arch/arm64/boot/bzImage
>   Error: 	../../arch/arm64/boot/bzImage
>   Error: 	/boot/vmlinuz-6.4.0
>   Error: 	/boot/bzImage-6.4.0

Up to you but I'd leave it simple like that if it's just to print an
occasional error message, it looks alright to me.

> 
> And this is how it looks now:
> 
>   Error: Could not find default kernel image in:
> 	./bzImage
> 	arch/arm64/boot/bzImage
> 	../../arch/arm64/boot/bzImage
> 	/boot/vmlinuz-6.4.0
> 	/boot/bzImage-6.4.0
> 
> That, and msg ends up being 5 * 4096 ~= 20k bytes in size.
> Happy to come up with something else if this is not satisfactory.
> 
>  arm/gic.c       |  5 ++--
>  builtin-run.c   | 68 ++++++++++++++++++++++++++++++++++---------------
>  builtin-setup.c | 18 ++++++-------
>  guest_compat.c  |  2 +-
>  kvm-cpu.c       | 12 ++++-----
>  mmio.c          | 10 ++++----
>  virtio/core.c   |  6 ++---
>  x86/ioport.c    | 11 ++++----
>  8 files changed, 78 insertions(+), 54 deletions(-)
> 
> diff --git a/arm/gic.c b/arm/gic.c
> index a223a72cfeb9..0795e9509bf8 100644
> --- a/arm/gic.c
> +++ b/arm/gic.c
> @@ -115,9 +115,8 @@ static int gic__create_its_frame(struct kvm *kvm, u64 its_frame_addr)
>  
>  	err = ioctl(kvm->vm_fd, KVM_CREATE_DEVICE, &its_device);
>  	if (err) {
> -		fprintf(stderr,
> -			"GICv3 ITS requested, but kernel does not support it.\n");
> -		fprintf(stderr, "Try --irqchip=gicv3 instead\n");
> +		pr_err("GICv3 ITS requested, but kernel does not support it.");
> +		pr_err("Try --irqchip=gicv3 instead");
>  		return err;
>  	}
>  
> diff --git a/builtin-run.c b/builtin-run.c
> index bd0d0b9c2467..79d031777c26 100644
> --- a/builtin-run.c
> +++ b/builtin-run.c
> @@ -271,12 +271,14 @@ static void *kvm_cpu_thread(void *arg)
>  	return (void *) (intptr_t) 0;
>  
>  panic_kvm:
> -	fprintf(stderr, "KVM exit reason: %u (\"%s\")\n",
> +	pr_err("KVM exit reason: %u (\"%s\")",
>  		current_kvm_cpu->kvm_run->exit_reason,
>  		kvm_exit_reasons[current_kvm_cpu->kvm_run->exit_reason]);
> -	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN)
> -		fprintf(stderr, "KVM exit code: 0x%llu\n",
> +
> +	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN) {
> +		pr_err("KVM exit code: 0x%llu",

Not your change but 0x%llu is wrong, it could be fixed here

>  			(unsigned long long)current_kvm_cpu->kvm_run->hw.hardware_exit_reason);
> +	}
>  
>  	kvm_cpu__set_debug_fd(STDOUT_FILENO);
>  	kvm_cpu__show_registers(current_kvm_cpu);
> @@ -310,28 +312,53 @@ static const char *default_vmlinux[] = {
>  
>  static void kernel_usage_with_options(void)
>  {
> -	const char **k;
> +	const char *prelude = "Could not find default kernel image in:";
>  	struct utsname uts;
> +	char *msg, *tmp;
> +	size_t msg_size;
> +	const char **k;
> +
> +	/* Ignore NULL path in host_kernels. */
> +	msg_size = PATH_MAX * (ARRAY_SIZE(host_kernels) - 1);
> +	msg_size += PATH_MAX * (ARRAY_SIZE(default_kernels) - 1);
> +	msg = calloc(msg_size, 1);
> +	if (!msg)
> +		die_perror("calloc");
> +	tmp = msg;
> +
> +	snprintf(tmp, msg_size, "%s\n", prelude);
> +	msg_size -= strlen(prelude) + 1;

msg_size didn't contain prelude

> +	tmp += strlen(prelude) + 1;
>  
> -	fprintf(stderr, "Fatal: could not find default kernel image in:\n");
>  	k = &default_kernels[0];
>  	while (*k) {
> -		fprintf(stderr, "\t%s\n", *k);
> +		if (snprintf(tmp, msg_size, "\t%s\n", *k) < 0)
> +			goto out;
> +		msg_size -= strlen(*k) + 2;
> +		tmp += strlen(*k) + 2;
>  		k++;
>  	}
>  
>  	if (uname(&uts) < 0)
> -		return;
> +		goto out;
>  
>  	k = &host_kernels[0];
>  	while (*k) {
>  		if (snprintf(kernel, PATH_MAX, "%s-%s", *k, uts.release) < 0)
> -			return;
> -		fprintf(stderr, "\t%s\n", kernel);
> +			goto out;
> +		if (snprintf(tmp, msg_size, "\t%s\n", kernel) < 0)
> +			goto out;
> +		msg_size -= strlen(kernel) + 2;
> +		tmp += strlen(kernel) + 2;
>  		k++;
>  	}
> -	fprintf(stderr, "\nPlease see '%s run --help' for more options.\n\n",
> +out:
> +	/* Remove trailing newline - pr_err() will add its own. */
> +	msg[strlen(msg) - 1] = '\0';
> +	pr_err("%s", msg);
> +	pr_info("Please see '%s run --help' for more options.",
>  		KVM_BINARY_NAME);
> +	free(msg);
>  }
>  
>  static u64 host_ram_size(void)
> @@ -656,8 +683,7 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
>  
>  			if ((kvm_run_wrapper == KVM_RUN_DEFAULT && kvm->cfg.kernel_filename) ||
>  				(kvm_run_wrapper == KVM_RUN_SANDBOX && kvm->cfg.sandbox)) {
> -				fprintf(stderr, "Cannot handle parameter: "
> -						"%s\n", argv[0]);
> +				pr_err("Cannot handle parameter: %s", argv[0]);
>  				usage_with_options(run_usage, options);
>  				free(kvm);
>  				return ERR_PTR(-EINVAL);
> @@ -775,15 +801,15 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
>  		kvm_run_set_real_cmdline(kvm);
>  
>  	if (kvm->cfg.kernel_filename) {
> -		printf("  # %s run -k %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
> -		       kvm->cfg.kernel_filename,
> -		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> -		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
> +		pr_info("# %s run -k %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
> +			kvm->cfg.kernel_filename,
> +			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> +			kvm->cfg.nrcpus, kvm->cfg.guest_name);
>  	} else if (kvm->cfg.firmware_filename) {
> -		printf("  # %s run --firmware %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
> -		       kvm->cfg.firmware_filename,
> -		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> -		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
> +		pr_info("# %s run --firmware %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
> +			kvm->cfg.firmware_filename,
> +			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> +			kvm->cfg.nrcpus, kvm->cfg.guest_name);
>  	}
>  
>  	if (init_list__init(kvm) < 0)
> @@ -815,7 +841,7 @@ static void kvm_cmd_run_exit(struct kvm *kvm, int guest_ret)
>  	init_list__exit(kvm);
>  
>  	if (guest_ret == 0)
> -		printf("\n  # KVM session ended normally.\n");
> +		pr_info("KVM session ended normally.");
>  }
>  
>  int kvm_cmd_run(int argc, const char **argv, const char *prefix)
> diff --git a/builtin-setup.c b/builtin-setup.c
> index b24d2a18921e..c333ae064b21 100644
> --- a/builtin-setup.c
> +++ b/builtin-setup.c
> @@ -271,15 +271,15 @@ int kvm_cmd_setup(int argc, const char **argv, const char *prefix)
>  		kvm_setup_help();
>  
>  	r = do_setup(instance_name);
> -	if (r == 0)
> -		printf("A new rootfs '%s' has been created in '%s%s'.\n\n"
> -			"You can now start it by running the following command:\n\n"
> -			"  %s run -d %s\n",
> -			instance_name, kvm__get_dir(), instance_name,
> -			KVM_BINARY_NAME,instance_name);
> -	else
> -		printf("Unable to create rootfs in %s%s: %s\n",
> -			kvm__get_dir(), instance_name, strerror(errno));
> +	if (r == 0) {
> +		pr_info("A new rootfs '%s' has been created in '%s%s'.",
> +			instance_name, kvm__get_dir(), instance_name);
> +		pr_info("You can now start it by running the following command:");
> +		pr_info("%s run -d %s", KVM_BINARY_NAME, instance_name);

Above uses '#' as prefix for a lkvm command, maybe we could keep it
consistent

> +	} else {
> +		pr_err("Unable to create rootfs in %s%s: %s",
> +		       kvm__get_dir(), instance_name, strerror(errno));
> +	}
>  
>  	return r;
>  }
> diff --git a/guest_compat.c b/guest_compat.c
> index fd4704b20b16..93f9aabcd6db 100644
> --- a/guest_compat.c
> +++ b/guest_compat.c
> @@ -86,7 +86,7 @@ int compat__print_all_messages(void)
>  
>  		msg = list_first_entry(&messages, struct compat_message, list);
>  
> -		printf("\n  # KVM compatibility warning.\n\t%s\n\t%s\n",
> +		pr_warning("KVM compatibility warning.\n\t%s\n\t%s",
>  			msg->title, msg->desc);
>  
>  		list_del(&msg->list);
> diff --git a/kvm-cpu.c b/kvm-cpu.c
> index 7dec08894cd3..1c566b3f21d6 100644
> --- a/kvm-cpu.c
> +++ b/kvm-cpu.c
> @@ -265,32 +265,32 @@ int kvm_cpu__init(struct kvm *kvm)
>  	recommended_cpus = kvm__recommended_cpus(kvm);
>  
>  	if (kvm->cfg.nrcpus > max_cpus) {
> -		printf("  # Limit the number of CPUs to %d\n", max_cpus);
> +		pr_warning("Limiting the number of CPUs to %d", max_cpus);
>  		kvm->cfg.nrcpus = max_cpus;
>  	} else if (kvm->cfg.nrcpus > recommended_cpus) {
> -		printf("  # Warning: The maximum recommended amount of VCPUs"
> -			" is %d\n", recommended_cpus);
> +		pr_warning("The maximum recommended amount of VCPUs is %d",
> +			   recommended_cpus);
>  	}
>  
>  	kvm->nrcpus = kvm->cfg.nrcpus;
>  
>  	task_eventfd = eventfd(0, 0);
>  	if (task_eventfd < 0) {
> -		pr_warning("Couldn't create task_eventfd");
> +		pr_err("Couldn't create task_eventfd");
>  		return task_eventfd;
>  	}
>  
>  	/* Alloc one pointer too many, so array ends up 0-terminated */
>  	kvm->cpus = calloc(kvm->nrcpus + 1, sizeof(void *));
>  	if (!kvm->cpus) {
> -		pr_warning("Couldn't allocate array for %d CPUs", kvm->nrcpus);
> +		pr_err("Couldn't allocate array for %d CPUs", kvm->nrcpus);
>  		return -ENOMEM;
>  	}
>  
>  	for (i = 0; i < kvm->nrcpus; i++) {
>  		kvm->cpus[i] = kvm_cpu__arch_init(kvm, i);
>  		if (!kvm->cpus[i]) {
> -			pr_warning("unable to initialize KVM VCPU");
> +			pr_err("unable to initialize KVM VCPU");
>  			goto fail_alloc;
>  		}
>  	}
> diff --git a/mmio.c b/mmio.c
> index 5a114e9997d9..d9a09565185c 100644
> --- a/mmio.c
> +++ b/mmio.c
> @@ -203,9 +203,9 @@ bool kvm__emulate_mmio(struct kvm_cpu *vcpu, u64 phys_addr, u8 *data,
>  	mmio = mmio_get(&mmio_tree, phys_addr, len);
>  	if (!mmio) {
>  		if (vcpu->kvm->cfg.mmio_debug)
> -			fprintf(stderr,	"Warning: Ignoring MMIO %s at %016llx (length %u)\n",
> -				to_direction(is_write),
> -				(unsigned long long)phys_addr, len);
> +			pr_warning("Warning: Ignoring MMIO %s at %016llx (length %u)",

"Warning:" is redundant

> +				   to_direction(is_write),
> +				   (unsigned long long)phys_addr, len);
>  		goto out;
>  	}
>  
> @@ -225,8 +225,8 @@ bool kvm__emulate_io(struct kvm_cpu *vcpu, u16 port, void *data,
>  	mmio = mmio_get(&pio_tree, port, size);
>  	if (!mmio) {
>  		if (vcpu->kvm->cfg.ioport_debug) {
> -			fprintf(stderr, "IO error: %s port=%x, size=%d, count=%u\n",
> -				to_direction(direction), port, size, count);
> +			pr_warning("IO error: %s port=%x, size=%d, count=%u",
> +				   to_direction(direction), port, size, count);
>  
>  			return false;
>  		}
> diff --git a/virtio/core.c b/virtio/core.c
> index a77e23bc9b34..c4e79c7a3d40 100644
> --- a/virtio/core.c
> +++ b/virtio/core.c
> @@ -417,10 +417,10 @@ int virtio_compat_add_message(const char *device, const char *config)
>  		return -ENOMEM;
>  	}
>  
> -	snprintf(title, len, "%s device was not detected.", device);
> -	snprintf(desc,  len, "While you have requested a %s device, "
> +	snprintf(title, len, "   %s device was not detected.", device);
> +	snprintf(desc,  len, "   While you have requested a %s device, "

Spaces seem redundant since there already is a \t prefix. I get this is to
align with "Warning:" but tab size can vary depending on the terminal.

>  			     "the guest kernel did not initialize it.\n"
> -			     "\tPlease make sure that the guest kernel was "
> +			     "\t   Please make sure that the guest kernel was "
>  			     "compiled with %s=y enabled in .config.",
>  			     device, config);
>  
> diff --git a/x86/ioport.c b/x86/ioport.c
> index 06b7defbaae8..0f1a857483c1 100644
> --- a/x86/ioport.c
> +++ b/x86/ioport.c
> @@ -14,9 +14,10 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
>  	if (!vcpu->kvm->cfg.ioport_debug)
>  		return;
>  
> -	fprintf(stderr, "debug port %s from VCPU%lu: port=0x%lx, size=%u",
> -		is_write ? "write" : "read", vcpu->cpu_id,
> -		(unsigned long)addr, len);
> +	pr_debug("debug port %s from VCPU%lu: port=0x%lx, size=%u",
> +		 is_write ? "write" : "read", vcpu->cpu_id,
> +		 (unsigned long)addr, len);
> +

This one is different: user enables ioport debugging with --debug-ioport
and expects to see these messages, even if loglevel < debug which is the
default. I think it should remain fprintf(). Though to be honest I don't
know if this is still supposed to work, currently kvm__emulate_io() exits
on the first ioport access when --debug-ioport is enabled.

Thanks,
Jean

>  	if (is_write) {
>  		u32 value;
>  
> @@ -26,9 +27,7 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
>  		case 4: value = ioport__read32((u32*)data); break;
>  		default: value = 0; break;
>  		}
> -		fprintf(stderr, ", data: 0x%x\n", value);
> -	} else {
> -		fprintf(stderr, "\n");
> +		pr_debug("data: 0x%x", value);
>  	}
>  }
>  
> -- 
> 2.41.0
> 

Re: [PATCH RESEND kvmtool 3/4] util: Use __pr_debug() instead of pr_info() to print debug messages

[Jean-Philippe Brucker]

On Fri, Jun 30, 2023 at 02:31:33PM +0100, Alexandru Elisei wrote:
> pr_debug() is special, because it can be suppressed with a command line
> argument, and because it needs to be a macro to capture the correct
> filename, function name and line number. Display debug messages with the
> prefix "Debug", to make it clear that those aren't informational messages.
> 
> Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>

Reviewed-by: Jean-Philippe Brucker <jean-philippe@linaro.org>

(nit below)

> ---
>  include/kvm/util.h |  3 ++-
>  util/util.c        | 15 +++++++++++++++
>  2 files changed, 17 insertions(+), 1 deletion(-)
> 
> diff --git a/include/kvm/util.h b/include/kvm/util.h
> index f51f370d2b37..6920ce2630ad 100644
> --- a/include/kvm/util.h
> +++ b/include/kvm/util.h
> @@ -42,12 +42,13 @@ extern void die_perror(const char *s) NORETURN;
>  extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
> +extern void __pr_debug(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
>  
>  #define pr_debug(fmt, ...)						\
>  	do {								\
>  		if (do_debug_print)					\
> -			pr_info("(%s) %s:%d: " fmt, __FILE__,		\
> +			__pr_debug("(%s) %s:%d: " fmt, __FILE__,	\
>  				__func__, __LINE__, ##__VA_ARGS__);	\
>  	} while (0)
>  
> diff --git a/util/util.c b/util/util.c
> index f59f26e1581c..e3b36f67f899 100644
> --- a/util/util.c
> +++ b/util/util.c
> @@ -38,6 +38,11 @@ static void info_builtin(const char *info, va_list params)
>  	report(" Info: ", info, params);
>  }
>  
> +static void debug_builtin(const char *info, va_list params)

parameter here and in __pr_debug could be called 'debug' for consistency

> +{
> +	report(" Debug: ", info, params);
> +}
> +
>  void die(const char *err, ...)
>  {
>  	va_list params;
> @@ -74,6 +79,16 @@ void pr_info(const char *info, ...)
>  	va_end(params);
>  }
>  
> +/* Do not call directly; call pr_debug() instead. */
> +void __pr_debug(const char *info, ...)
> +{
> +	va_list params;
> +
> +	va_start(params, info);
> +	debug_builtin(info, params);
> +	va_end(params);
> +}
> +
>  void die_perror(const char *s)
>  {
>  	perror(s);
> -- 
> 2.41.0
> 

Re: [PATCH RESEND kvmtool 4/4] Add --loglevel argument for the run command

[Jean-Philippe Brucker]

On Fri, Jun 30, 2023 at 02:31:34PM +0100, Alexandru Elisei wrote:
> Add --loglevel command line argument, with the possible values of 'error',
> 'warning', 'info' or 'debug' to control what messages kvmtool displays. The
> argument functions similarly to the Linux kernel parameter, when lower
> verbosity levels hide all message with a higher verbosity (for example,
> 'warning' hides info and debug messages, allows warning and error
> messsages).
> 
> The default level is 'info', to match the current behaviour. --debug has
> been kept as a legacy option, which might be removed in the future.
> 
> Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>

Reviewed-by: Jean-Philippe Brucker <jean-philippe@linaro.org>

> ---
>  builtin-run.c      | 32 ++++++++++++++++++++++++++++----
>  include/kvm/util.h |  9 +++++++--
>  util/util.c        |  9 +++++++++
>  3 files changed, 44 insertions(+), 6 deletions(-)
> 
> diff --git a/builtin-run.c b/builtin-run.c
> index 79d031777c26..2e4378819f00 100644
> --- a/builtin-run.c
> +++ b/builtin-run.c
> @@ -58,8 +58,7 @@
>  __thread struct kvm_cpu *current_kvm_cpu;
>  
>  static int  kvm_run_wrapper;
> -
> -bool do_debug_print = false;
> +int loglevel = LOGLEVEL_INFO;
>  
>  static const char * const run_usage[] = {
>  	"lkvm run [<options>] [<kernel image>]",
> @@ -146,6 +145,27 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
>  	return 0;
>  }
>  
> +static int loglevel_parser(const struct option *opt, const char *arg, int unset)
> +{
> +	if (strcmp(opt->long_name, "debug") == 0) {
> +		loglevel = LOGLEVEL_DEBUG;
> +		return 0;
> +	}
> +
> +	if (strcmp(arg, "debug") == 0)
> +		loglevel = LOGLEVEL_DEBUG;
> +	else if (strcmp(arg, "info") == 0)
> +		loglevel = LOGLEVEL_INFO;
> +	else if (strcmp(arg, "warning") == 0)
> +		loglevel = LOGLEVEL_WARNING;
> +	else if (strcmp(arg, "error") == 0)
> +		loglevel = LOGLEVEL_ERROR;
> +	else
> +		die("Unknown loglevel: %s", arg);
> +
> +	return 0;
> +}
> +
>  #ifndef OPT_ARCH_RUN
>  #define OPT_ARCH_RUN(...)
>  #endif
> @@ -215,6 +235,8 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
>  		     VIRTIO_TRANS_OPT_HELP_SHORT,		        \
>  		     "Type of virtio transport",			\
>  		     virtio_transport_parser, NULL),			\
> +	OPT_CALLBACK('\0', "loglevel", NULL, "[error|warning|info|debug]",\
> +			"Set the verbosity level", loglevel_parser, NULL),\
>  									\
>  	OPT_GROUP("Kernel options:"),					\
>  	OPT_STRING('k', "kernel", &(cfg)->kernel_filename, "kernel",	\
> @@ -241,8 +263,10 @@ static int mem_parser(const struct option *opt, const char *arg, int unset)
>  		     vfio_device_parser, kvm),				\
>  									\
>  	OPT_GROUP("Debug options:"),					\
> -	OPT_BOOLEAN('\0', "debug", &do_debug_print,			\
> -			"Enable debug messages"),			\
> +	OPT_CALLBACK_NOOPT('\0', "debug", kvm, NULL,			\
> +			"Enable debug messages (deprecated, use "	\
> +			"--loglevel=debug instead)",			\
> +			loglevel_parser, NULL),				\
>  	OPT_BOOLEAN('\0', "debug-single-step", &(cfg)->single_step,	\
>  			"Enable single stepping"),			\
>  	OPT_BOOLEAN('\0', "debug-ioport", &(cfg)->ioport_debug,		\
> diff --git a/include/kvm/util.h b/include/kvm/util.h
> index 6920ce2630ad..e9d63c184752 100644
> --- a/include/kvm/util.h
> +++ b/include/kvm/util.h
> @@ -32,7 +32,10 @@
>  #endif
>  #endif
>  
> -extern bool do_debug_print;
> +#define LOGLEVEL_ERROR		0
> +#define LOGLEVEL_WARNING	1
> +#define LOGLEVEL_INFO		2
> +#define LOGLEVEL_DEBUG		3
>  
>  #define PROT_RW (PROT_READ|PROT_WRITE)
>  #define MAP_ANON_NORESERVE (MAP_PRIVATE | MAP_ANONYMOUS | MAP_NORESERVE)
> @@ -45,9 +48,11 @@ extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)))
>  extern void __pr_debug(const char *err, ...) __attribute__((format (printf, 1, 2)));
>  extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
>  
> +extern int loglevel;
> +
>  #define pr_debug(fmt, ...)						\
>  	do {								\
> -		if (do_debug_print)					\
> +		if (loglevel >= LOGLEVEL_DEBUG)				\
>  			__pr_debug("(%s) %s:%d: " fmt, __FILE__,	\
>  				__func__, __LINE__, ##__VA_ARGS__);	\
>  	} while (0)
> diff --git a/util/util.c b/util/util.c
> index e3b36f67f899..962e8d4edb21 100644
> --- a/util/util.c
> +++ b/util/util.c
> @@ -56,6 +56,9 @@ void pr_err(const char *err, ...)
>  {
>  	va_list params;
>  
> +	if (loglevel < LOGLEVEL_ERROR)
> +		return;
> +
>  	va_start(params, err);
>  	error_builtin(err, params);
>  	va_end(params);
> @@ -65,6 +68,9 @@ void pr_warning(const char *warn, ...)
>  {
>  	va_list params;
>  
> +	if (loglevel < LOGLEVEL_WARNING)
> +		return;
> +
>  	va_start(params, warn);
>  	warn_builtin(warn, params);
>  	va_end(params);
> @@ -74,6 +80,9 @@ void pr_info(const char *info, ...)
>  {
>  	va_list params;
>  
> +	if (loglevel < LOGLEVEL_INFO)
> +		return;
> +
>  	va_start(params, info);
>  	info_builtin(info, params);
>  	va_end(params);
> -- 
> 2.41.0
> 

Re: [PATCH RESEND kvmtool 1/4] util: Make pr_err() return void

[Alexandru Elisei]

Hi Jean-Philippe,

On Tue, Jul 04, 2023 at 10:37:17AM +0100, Jean-Philippe Brucker wrote:
> On Fri, Jun 30, 2023 at 02:31:31PM +0100, Alexandru Elisei wrote:
> > Of all the pr_* functions, pr_err() is the only function that returns a
> > value, which is -1. The code in parse_options is the only code that relies
> > on pr_err() returning a value, and that value must be exactly -1, because
> > it is being treated differently than the other return values.
> > 
> > This makes the code opaque, because it's not immediately obvious where that
> > value comes from, and fragile, as a change in the return value of pr_err
> > would break it.
> > 
> > Make pr_err() more like the other functions and don't return a value.
> > 
> > Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
> 
> One small nit below, otherwise 
> 
> Reviewed-by: Jean-Philippe Brucker <jean-philippe@linaro.org>

Thank you for the review!

> 
> > ---
> >  include/kvm/util.h   |  2 +-
> >  util/parse-options.c | 28 ++++++++++++++++------------
> >  util/util.c          |  3 +--
> >  3 files changed, 18 insertions(+), 15 deletions(-)
> > 
> > diff --git a/include/kvm/util.h b/include/kvm/util.h
> > index b49454876a83..f51f370d2b37 100644
> > --- a/include/kvm/util.h
> > +++ b/include/kvm/util.h
> > @@ -39,7 +39,7 @@ extern bool do_debug_print;
> >  
> >  extern void die(const char *err, ...) NORETURN __attribute__((format (printf, 1, 2)));
> >  extern void die_perror(const char *s) NORETURN;
> > -extern int pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
> > +extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
> > diff --git a/util/parse-options.c b/util/parse-options.c
> > index 9a1bbee6c271..fb44b48d14c8 100644
> > --- a/util/parse-options.c
> > +++ b/util/parse-options.c
> > @@ -17,10 +17,13 @@
> >  static int opterror(const struct option *opt, const char *reason, int flags)
> >  {
> >  	if (flags & OPT_SHORT)
> > -		return pr_err("switch `%c' %s", opt->short_name, reason);
> > -	if (flags & OPT_UNSET)
> > -		return pr_err("option `no-%s' %s", opt->long_name, reason);
> > -	return pr_err("option `%s' %s", opt->long_name, reason);
> > +		pr_err("switch `%c' %s", opt->short_name, reason);
> > +	else if (flags & OPT_UNSET)
> > +		pr_err("option `no-%s' %s", opt->long_name, reason);
> > +	else
> > +		pr_err("option `%s' %s", opt->long_name, reason);
> > +
> > +	return -1;
> >  }
> >  
> >  static int get_arg(struct parse_opt_ctx_t *p, const struct option *opt,
> > @@ -429,14 +432,15 @@ is_abbreviated:
> >  		return get_value(p, options, flags);
> >  	}
> >  
> > -	if (ambiguous_option)
> > -		return pr_err("Ambiguous option: %s "
> > -				"(could be --%s%s or --%s%s)",
> > -				arg,
> > -				(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
> > -				ambiguous_option->long_name,
> > -				(abbrev_flags & OPT_UNSET) ?  "no-" : "",
> > -				abbrev_option->long_name);
> > +	if (ambiguous_option) {
> > +		pr_err("Ambiguous option: %s " "(could be --%s%s or --%s%s)",
> 
> drop " "

Done.

Thanks,
Alex

> 
> > +			arg,
> > +			(ambiguous_flags & OPT_UNSET) ?  "no-" : "",
> > +			ambiguous_option->long_name,
> > +			(abbrev_flags & OPT_UNSET) ?  "no-" : "",
> > +			abbrev_option->long_name);
> > +		return -1;
> > +	}
> >  	if (abbrev_option)
> >  		return get_value(p, abbrev_option, abbrev_flags);
> >  	return -2;
> > diff --git a/util/util.c b/util/util.c
> > index 1877105e3c08..f59f26e1581c 100644
> > --- a/util/util.c
> > +++ b/util/util.c
> > @@ -47,14 +47,13 @@ void die(const char *err, ...)
> >  	va_end(params);
> >  }
> >  
> > -int pr_err(const char *err, ...)
> > +void pr_err(const char *err, ...)
> >  {
> >  	va_list params;
> >  
> >  	va_start(params, err);
> >  	error_builtin(err, params);
> >  	va_end(params);
> > -	return -1;
> >  }
> >  
> >  void pr_warning(const char *warn, ...)
> > -- 
> > 2.41.0
> > 

Re: [PATCH RESEND kvmtool 2/4] Replace printf/fprintf with pr_* macros

[Alexandru Elisei]

Hi,

On Tue, Jul 04, 2023 at 10:46:36AM +0100, Jean-Philippe Brucker wrote:
> On Fri, Jun 30, 2023 at 02:31:32PM +0100, Alexandru Elisei wrote:
> > To prepare for allowing finer control over the messages that kvmtool
> > displays, replace printf() and fprintf() with the pr_* macros.
> > 
> > Minor changes were made to fix coding style issues that were pet peeves for
> > the author. And use pr_err() in kvm_cpu__init() instead of pr_warning() for
> > fatal errors.
> > 
> > Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
> 
> Looks good, some small things below
> 
> > ---
> > I have my doubts about the change to kernel_usage_with_options(). I did
> > this way instead of replacing fprintf() with pr_err() because this is how
> > it would have looked like:
> > 
> >   Error: Could not find default kernel image in:
> >   Error: 	./bzImage
> >   Error: 	arch/arm64/boot/bzImage
> >   Error: 	../../arch/arm64/boot/bzImage
> >   Error: 	/boot/vmlinuz-6.4.0
> >   Error: 	/boot/bzImage-6.4.0
> 
> Up to you but I'd leave it simple like that if it's just to print an
> occasional error message, it looks alright to me.

I went back to using pr_err().

> 
> > 
> > And this is how it looks now:
> > 
> >   Error: Could not find default kernel image in:
> > 	./bzImage
> > 	arch/arm64/boot/bzImage
> > 	../../arch/arm64/boot/bzImage
> > 	/boot/vmlinuz-6.4.0
> > 	/boot/bzImage-6.4.0
> > 
> > That, and msg ends up being 5 * 4096 ~= 20k bytes in size.
> > Happy to come up with something else if this is not satisfactory.
> > 
> >  arm/gic.c       |  5 ++--
> >  builtin-run.c   | 68 ++++++++++++++++++++++++++++++++++---------------
> >  builtin-setup.c | 18 ++++++-------
> >  guest_compat.c  |  2 +-
> >  kvm-cpu.c       | 12 ++++-----
> >  mmio.c          | 10 ++++----
> >  virtio/core.c   |  6 ++---
> >  x86/ioport.c    | 11 ++++----
> >  8 files changed, 78 insertions(+), 54 deletions(-)
> > 
> > diff --git a/arm/gic.c b/arm/gic.c
> > index a223a72cfeb9..0795e9509bf8 100644
> > --- a/arm/gic.c
> > +++ b/arm/gic.c
> > @@ -115,9 +115,8 @@ static int gic__create_its_frame(struct kvm *kvm, u64 its_frame_addr)
> >  
> >  	err = ioctl(kvm->vm_fd, KVM_CREATE_DEVICE, &its_device);
> >  	if (err) {
> > -		fprintf(stderr,
> > -			"GICv3 ITS requested, but kernel does not support it.\n");
> > -		fprintf(stderr, "Try --irqchip=gicv3 instead\n");
> > +		pr_err("GICv3 ITS requested, but kernel does not support it.");
> > +		pr_err("Try --irqchip=gicv3 instead");
> >  		return err;
> >  	}
> >  
> > diff --git a/builtin-run.c b/builtin-run.c
> > index bd0d0b9c2467..79d031777c26 100644
> > --- a/builtin-run.c
> > +++ b/builtin-run.c
> > @@ -271,12 +271,14 @@ static void *kvm_cpu_thread(void *arg)
> >  	return (void *) (intptr_t) 0;
> >  
> >  panic_kvm:
> > -	fprintf(stderr, "KVM exit reason: %u (\"%s\")\n",
> > +	pr_err("KVM exit reason: %u (\"%s\")",
> >  		current_kvm_cpu->kvm_run->exit_reason,
> >  		kvm_exit_reasons[current_kvm_cpu->kvm_run->exit_reason]);
> > -	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN)
> > -		fprintf(stderr, "KVM exit code: 0x%llu\n",
> > +
> > +	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN) {
> > +		pr_err("KVM exit code: 0x%llu",
> 
> Not your change but 0x%llu is wrong, it could be fixed here

Not sure what you mean, hardware_exit_reason is an u64, and it's cast to an
unsigned long long to avoid printf format specifier warnings.

And as far as I know, unsigned long long is at least 64bits according to
C99 (the only reference I was able to quickly find is LLONG_MIN being
defined as -(2^63 - 1)).

> 
> >  			(unsigned long long)current_kvm_cpu->kvm_run->hw.hardware_exit_reason);
> > +	}
> >  
> >  	kvm_cpu__set_debug_fd(STDOUT_FILENO);
> >  	kvm_cpu__show_registers(current_kvm_cpu);
> > @@ -310,28 +312,53 @@ static const char *default_vmlinux[] = {
> >  
> >  static void kernel_usage_with_options(void)
> >  {
> > -	const char **k;
> > +	const char *prelude = "Could not find default kernel image in:";
> >  	struct utsname uts;
> > +	char *msg, *tmp;
> > +	size_t msg_size;
> > +	const char **k;
> > +
> > +	/* Ignore NULL path in host_kernels. */
> > +	msg_size = PATH_MAX * (ARRAY_SIZE(host_kernels) - 1);
> > +	msg_size += PATH_MAX * (ARRAY_SIZE(default_kernels) - 1);
> > +	msg = calloc(msg_size, 1);
> > +	if (!msg)
> > +		die_perror("calloc");
> > +	tmp = msg;
> > +
> > +	snprintf(tmp, msg_size, "%s\n", prelude);
> > +	msg_size -= strlen(prelude) + 1;
> 
> msg_size didn't contain prelude

Removed all of this to use pr_err instead of fprint(stderr). Seems easier
this way, and less error prone.

> 
> > +	tmp += strlen(prelude) + 1;
> >  
> > -	fprintf(stderr, "Fatal: could not find default kernel image in:\n");
> >  	k = &default_kernels[0];
> >  	while (*k) {
> > -		fprintf(stderr, "\t%s\n", *k);
> > +		if (snprintf(tmp, msg_size, "\t%s\n", *k) < 0)
> > +			goto out;
> > +		msg_size -= strlen(*k) + 2;
> > +		tmp += strlen(*k) + 2;
> >  		k++;
> >  	}
> >  
> >  	if (uname(&uts) < 0)
> > -		return;
> > +		goto out;
> >  
> >  	k = &host_kernels[0];
> >  	while (*k) {
> >  		if (snprintf(kernel, PATH_MAX, "%s-%s", *k, uts.release) < 0)
> > -			return;
> > -		fprintf(stderr, "\t%s\n", kernel);
> > +			goto out;
> > +		if (snprintf(tmp, msg_size, "\t%s\n", kernel) < 0)
> > +			goto out;
> > +		msg_size -= strlen(kernel) + 2;
> > +		tmp += strlen(kernel) + 2;
> >  		k++;
> >  	}
> > -	fprintf(stderr, "\nPlease see '%s run --help' for more options.\n\n",
> > +out:
> > +	/* Remove trailing newline - pr_err() will add its own. */
> > +	msg[strlen(msg) - 1] = '\0';
> > +	pr_err("%s", msg);
> > +	pr_info("Please see '%s run --help' for more options.",
> >  		KVM_BINARY_NAME);
> > +	free(msg);
> >  }
> >  
> >  static u64 host_ram_size(void)
> > @@ -656,8 +683,7 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
> >  
> >  			if ((kvm_run_wrapper == KVM_RUN_DEFAULT && kvm->cfg.kernel_filename) ||
> >  				(kvm_run_wrapper == KVM_RUN_SANDBOX && kvm->cfg.sandbox)) {
> > -				fprintf(stderr, "Cannot handle parameter: "
> > -						"%s\n", argv[0]);
> > +				pr_err("Cannot handle parameter: %s", argv[0]);
> >  				usage_with_options(run_usage, options);
> >  				free(kvm);
> >  				return ERR_PTR(-EINVAL);
> > @@ -775,15 +801,15 @@ static struct kvm *kvm_cmd_run_init(int argc, const char **argv)
> >  		kvm_run_set_real_cmdline(kvm);
> >  
> >  	if (kvm->cfg.kernel_filename) {
> > -		printf("  # %s run -k %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
> > -		       kvm->cfg.kernel_filename,
> > -		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> > -		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
> > +		pr_info("# %s run -k %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
> > +			kvm->cfg.kernel_filename,
> > +			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> > +			kvm->cfg.nrcpus, kvm->cfg.guest_name);
> >  	} else if (kvm->cfg.firmware_filename) {
> > -		printf("  # %s run --firmware %s -m %Lu -c %d --name %s\n", KVM_BINARY_NAME,
> > -		       kvm->cfg.firmware_filename,
> > -		       (unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> > -		       kvm->cfg.nrcpus, kvm->cfg.guest_name);
> > +		pr_info("# %s run --firmware %s -m %Lu -c %d --name %s", KVM_BINARY_NAME,
> > +			kvm->cfg.firmware_filename,
> > +			(unsigned long long)kvm->cfg.ram_size >> MB_SHIFT,
> > +			kvm->cfg.nrcpus, kvm->cfg.guest_name);
> >  	}
> >  
> >  	if (init_list__init(kvm) < 0)
> > @@ -815,7 +841,7 @@ static void kvm_cmd_run_exit(struct kvm *kvm, int guest_ret)
> >  	init_list__exit(kvm);
> >  
> >  	if (guest_ret == 0)
> > -		printf("\n  # KVM session ended normally.\n");
> > +		pr_info("KVM session ended normally.");
> >  }
> >  
> >  int kvm_cmd_run(int argc, const char **argv, const char *prefix)
> > diff --git a/builtin-setup.c b/builtin-setup.c
> > index b24d2a18921e..c333ae064b21 100644
> > --- a/builtin-setup.c
> > +++ b/builtin-setup.c
> > @@ -271,15 +271,15 @@ int kvm_cmd_setup(int argc, const char **argv, const char *prefix)
> >  		kvm_setup_help();
> >  
> >  	r = do_setup(instance_name);
> > -	if (r == 0)
> > -		printf("A new rootfs '%s' has been created in '%s%s'.\n\n"
> > -			"You can now start it by running the following command:\n\n"
> > -			"  %s run -d %s\n",
> > -			instance_name, kvm__get_dir(), instance_name,
> > -			KVM_BINARY_NAME,instance_name);
> > -	else
> > -		printf("Unable to create rootfs in %s%s: %s\n",
> > -			kvm__get_dir(), instance_name, strerror(errno));
> > +	if (r == 0) {
> > +		pr_info("A new rootfs '%s' has been created in '%s%s'.",
> > +			instance_name, kvm__get_dir(), instance_name);
> > +		pr_info("You can now start it by running the following command:");
> > +		pr_info("%s run -d %s", KVM_BINARY_NAME, instance_name);
> 
> Above uses '#' as prefix for a lkvm command, maybe we could keep it
> consistent
> 
> > +	} else {
> > +		pr_err("Unable to create rootfs in %s%s: %s",
> > +		       kvm__get_dir(), instance_name, strerror(errno));
> > +	}
> >  
> >  	return r;
> >  }
> > diff --git a/guest_compat.c b/guest_compat.c
> > index fd4704b20b16..93f9aabcd6db 100644
> > --- a/guest_compat.c
> > +++ b/guest_compat.c
> > @@ -86,7 +86,7 @@ int compat__print_all_messages(void)
> >  
> >  		msg = list_first_entry(&messages, struct compat_message, list);
> >  
> > -		printf("\n  # KVM compatibility warning.\n\t%s\n\t%s\n",
> > +		pr_warning("KVM compatibility warning.\n\t%s\n\t%s",
> >  			msg->title, msg->desc);
> >  
> >  		list_del(&msg->list);
> > diff --git a/kvm-cpu.c b/kvm-cpu.c
> > index 7dec08894cd3..1c566b3f21d6 100644
> > --- a/kvm-cpu.c
> > +++ b/kvm-cpu.c
> > @@ -265,32 +265,32 @@ int kvm_cpu__init(struct kvm *kvm)
> >  	recommended_cpus = kvm__recommended_cpus(kvm);
> >  
> >  	if (kvm->cfg.nrcpus > max_cpus) {
> > -		printf("  # Limit the number of CPUs to %d\n", max_cpus);
> > +		pr_warning("Limiting the number of CPUs to %d", max_cpus);
> >  		kvm->cfg.nrcpus = max_cpus;
> >  	} else if (kvm->cfg.nrcpus > recommended_cpus) {
> > -		printf("  # Warning: The maximum recommended amount of VCPUs"
> > -			" is %d\n", recommended_cpus);
> > +		pr_warning("The maximum recommended amount of VCPUs is %d",
> > +			   recommended_cpus);
> >  	}
> >  
> >  	kvm->nrcpus = kvm->cfg.nrcpus;
> >  
> >  	task_eventfd = eventfd(0, 0);
> >  	if (task_eventfd < 0) {
> > -		pr_warning("Couldn't create task_eventfd");
> > +		pr_err("Couldn't create task_eventfd");
> >  		return task_eventfd;
> >  	}
> >  
> >  	/* Alloc one pointer too many, so array ends up 0-terminated */
> >  	kvm->cpus = calloc(kvm->nrcpus + 1, sizeof(void *));
> >  	if (!kvm->cpus) {
> > -		pr_warning("Couldn't allocate array for %d CPUs", kvm->nrcpus);
> > +		pr_err("Couldn't allocate array for %d CPUs", kvm->nrcpus);
> >  		return -ENOMEM;
> >  	}
> >  
> >  	for (i = 0; i < kvm->nrcpus; i++) {
> >  		kvm->cpus[i] = kvm_cpu__arch_init(kvm, i);
> >  		if (!kvm->cpus[i]) {
> > -			pr_warning("unable to initialize KVM VCPU");
> > +			pr_err("unable to initialize KVM VCPU");
> >  			goto fail_alloc;
> >  		}
> >  	}
> > diff --git a/mmio.c b/mmio.c
> > index 5a114e9997d9..d9a09565185c 100644
> > --- a/mmio.c
> > +++ b/mmio.c
> > @@ -203,9 +203,9 @@ bool kvm__emulate_mmio(struct kvm_cpu *vcpu, u64 phys_addr, u8 *data,
> >  	mmio = mmio_get(&mmio_tree, phys_addr, len);
> >  	if (!mmio) {
> >  		if (vcpu->kvm->cfg.mmio_debug)
> > -			fprintf(stderr,	"Warning: Ignoring MMIO %s at %016llx (length %u)\n",
> > -				to_direction(is_write),
> > -				(unsigned long long)phys_addr, len);
> > +			pr_warning("Warning: Ignoring MMIO %s at %016llx (length %u)",
> 
> "Warning:" is redundant

I've reverted this change, for the same reason I reverted the ioport change
(it's a separate debug option).

Also replaced "Warning" with "IO warning" to be consistent with "IO error"
below and to make it clear that it's separate from the pr_* messages ( it's
not toggled with a --loglevel level).

> 
> > +				   to_direction(is_write),
> > +				   (unsigned long long)phys_addr, len);
> >  		goto out;
> >  	}
> >  
> > @@ -225,8 +225,8 @@ bool kvm__emulate_io(struct kvm_cpu *vcpu, u16 port, void *data,
> >  	mmio = mmio_get(&pio_tree, port, size);
> >  	if (!mmio) {
> >  		if (vcpu->kvm->cfg.ioport_debug) {
> > -			fprintf(stderr, "IO error: %s port=%x, size=%d, count=%u\n",
> > -				to_direction(direction), port, size, count);
> > +			pr_warning("IO error: %s port=%x, size=%d, count=%u",
> > +				   to_direction(direction), port, size, count);
> >  
> >  			return false;
> >  		}
> > diff --git a/virtio/core.c b/virtio/core.c
> > index a77e23bc9b34..c4e79c7a3d40 100644
> > --- a/virtio/core.c
> > +++ b/virtio/core.c
> > @@ -417,10 +417,10 @@ int virtio_compat_add_message(const char *device, const char *config)
> >  		return -ENOMEM;
> >  	}
> >  
> > -	snprintf(title, len, "%s device was not detected.", device);
> > -	snprintf(desc,  len, "While you have requested a %s device, "
> > +	snprintf(title, len, "   %s device was not detected.", device);
> > +	snprintf(desc,  len, "   While you have requested a %s device, "
> 
> Spaces seem redundant since there already is a \t prefix. I get this is to
> align with "Warning:" but tab size can vary depending on the terminal.

Done.

> 
> >  			     "the guest kernel did not initialize it.\n"
> > -			     "\tPlease make sure that the guest kernel was "
> > +			     "\t   Please make sure that the guest kernel was "
> >  			     "compiled with %s=y enabled in .config.",
> >  			     device, config);
> >  
> > diff --git a/x86/ioport.c b/x86/ioport.c
> > index 06b7defbaae8..0f1a857483c1 100644
> > --- a/x86/ioport.c
> > +++ b/x86/ioport.c
> > @@ -14,9 +14,10 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
> >  	if (!vcpu->kvm->cfg.ioport_debug)
> >  		return;
> >  
> > -	fprintf(stderr, "debug port %s from VCPU%lu: port=0x%lx, size=%u",
> > -		is_write ? "write" : "read", vcpu->cpu_id,
> > -		(unsigned long)addr, len);
> > +	pr_debug("debug port %s from VCPU%lu: port=0x%lx, size=%u",
> > +		 is_write ? "write" : "read", vcpu->cpu_id,
> > +		 (unsigned long)addr, len);
> > +
> 
> This one is different: user enables ioport debugging with --debug-ioport
> and expects to see these messages, even if loglevel < debug which is the
> default. I think it should remain fprintf(). Though to be honest I don't
> know if this is still supposed to work, currently kvm__emulate_io() exits
> on the first ioport access when --debug-ioport is enabled.

Agreed, I've reverted this change.

Thanks,
Alex

> 
> Thanks,
> Jean
> 
> >  	if (is_write) {
> >  		u32 value;
> >  
> > @@ -26,9 +27,7 @@ static void debug_io(struct kvm_cpu *vcpu, u64 addr, u8 *data, u32 len,
> >  		case 4: value = ioport__read32((u32*)data); break;
> >  		default: value = 0; break;
> >  		}
> > -		fprintf(stderr, ", data: 0x%x\n", value);
> > -	} else {
> > -		fprintf(stderr, "\n");
> > +		pr_debug("data: 0x%x", value);
> >  	}
> >  }
> >  
> > -- 
> > 2.41.0
> > 

Re: [PATCH RESEND kvmtool 3/4] util: Use __pr_debug() instead of pr_info() to print debug messages

[Alexandru Elisei]

Hi,

On Tue, Jul 04, 2023 at 10:50:04AM +0100, Jean-Philippe Brucker wrote:
> On Fri, Jun 30, 2023 at 02:31:33PM +0100, Alexandru Elisei wrote:
> > pr_debug() is special, because it can be suppressed with a command line
> > argument, and because it needs to be a macro to capture the correct
> > filename, function name and line number. Display debug messages with the
> > prefix "Debug", to make it clear that those aren't informational messages.
> > 
> > Signed-off-by: Alexandru Elisei <alexandru.elisei@arm.com>
> 
> Reviewed-by: Jean-Philippe Brucker <jean-philippe@linaro.org>

Thanks, changed the parameter to be called debug.

Alex

> 
> (nit below)
> 
> > ---
> >  include/kvm/util.h |  3 ++-
> >  util/util.c        | 15 +++++++++++++++
> >  2 files changed, 17 insertions(+), 1 deletion(-)
> > 
> > diff --git a/include/kvm/util.h b/include/kvm/util.h
> > index f51f370d2b37..6920ce2630ad 100644
> > --- a/include/kvm/util.h
> > +++ b/include/kvm/util.h
> > @@ -42,12 +42,13 @@ extern void die_perror(const char *s) NORETURN;
> >  extern void pr_err(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void pr_warning(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void pr_info(const char *err, ...) __attribute__((format (printf, 1, 2)));
> > +extern void __pr_debug(const char *err, ...) __attribute__((format (printf, 1, 2)));
> >  extern void set_die_routine(void (*routine)(const char *err, va_list params) NORETURN);
> >  
> >  #define pr_debug(fmt, ...)						\
> >  	do {								\
> >  		if (do_debug_print)					\
> > -			pr_info("(%s) %s:%d: " fmt, __FILE__,		\
> > +			__pr_debug("(%s) %s:%d: " fmt, __FILE__,	\
> >  				__func__, __LINE__, ##__VA_ARGS__);	\
> >  	} while (0)
> >  
> > diff --git a/util/util.c b/util/util.c
> > index f59f26e1581c..e3b36f67f899 100644
> > --- a/util/util.c
> > +++ b/util/util.c
> > @@ -38,6 +38,11 @@ static void info_builtin(const char *info, va_list params)
> >  	report(" Info: ", info, params);
> >  }
> >  
> > +static void debug_builtin(const char *info, va_list params)
> 
> parameter here and in __pr_debug could be called 'debug' for consistency
> 
> > +{
> > +	report(" Debug: ", info, params);
> > +}
> > +
> >  void die(const char *err, ...)
> >  {
> >  	va_list params;
> > @@ -74,6 +79,16 @@ void pr_info(const char *info, ...)
> >  	va_end(params);
> >  }
> >  
> > +/* Do not call directly; call pr_debug() instead. */
> > +void __pr_debug(const char *info, ...)
> > +{
> > +	va_list params;
> > +
> > +	va_start(params, info);
> > +	debug_builtin(info, params);
> > +	va_end(params);
> > +}
> > +
> >  void die_perror(const char *s)
> >  {
> >  	perror(s);
> > -- 
> > 2.41.0
> > 

Re: [PATCH RESEND kvmtool 2/4] Replace printf/fprintf with pr_* macros

[Jean-Philippe Brucker]

On Fri, Jul 07, 2023 at 02:29:12PM +0100, Alexandru Elisei wrote:
> > > -	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN)
> > > -		fprintf(stderr, "KVM exit code: 0x%llu\n",
> > > +
> > > +	if (current_kvm_cpu->kvm_run->exit_reason == KVM_EXIT_UNKNOWN) {
> > > +		pr_err("KVM exit code: 0x%llu",
> > 
> > Not your change but 0x%llu is wrong, it could be fixed here
> 
> Not sure what you mean, hardware_exit_reason is an u64, and it's cast to an
> unsigned long long to avoid printf format specifier warnings.
> 
> And as far as I know, unsigned long long is at least 64bits according to
> C99 (the only reference I was able to quickly find is LLONG_MIN being
> defined as -(2^63 - 1)).

Sorry I meant the 0x prefix is wrong because we're printing a decimal
number, not hexadecimal

Thanks,
Jean