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

[Jean-Philippe Brucker <jean-philippe@linaro.org>]

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
>