bhyve: Replace many fprintf(stderr, ...) calls with EPRINTLN

EPRINTLN handles newlines appropriately when stdout/stderr have been
reused as the backend for a serial port.

For bhyverun.c itself, the rule this attempts to follow is to use
regular fprintf/perror/warn/err prior to init_pci() (which is when
serial ports are configured) and to switch to EPRINTLN afterwards.

Reviewed by:	corvink, markj
Differential Revision:	https://reviews.freebsd.org/D42182

(cherry picked from commit b0936440b8fcee523c0b26fdbbef7c3b2b5098bf)

11 files changed, 69 insertions, 68 deletions

diff --git a/usr.sbin/bhyve/amd64/bhyverun_machdep.c b/usr.sbin/bhyve/amd64/bhyverun_machdep.c
index 9254fb5f94a0..70f6a6ae1c0a 100644
--- a/usr.sbin/bhyve/amd64/bhyverun_machdep.c
+++ b/usr.sbin/bhyve/amd64/bhyverun_machdep.c
@@ -37,6 +37,7 @@
 #include "atkbdc.h"
 #include "bhyverun.h"
 #include "config.h"
+#include "debug.h"
 #include "e820.h"
 #include "fwctl.h"
 #include "ioapic.h"
@@ -70,7 +71,7 @@ bhyve_init_vcpu(struct vcpu *vcpu)
 	if (get_config_bool_default("x86.vmexit_on_hlt", false)) {
 		err = vm_get_capability(vcpu, VM_CAP_HALT_EXIT, &tmp);
 		if (err < 0) {
-			fprintf(stderr, "VM exit on HLT not supported\n");
+			EPRINTLN("VM exit on HLT not supported");
 			exit(4);
 		}
 		vm_set_capability(vcpu, VM_CAP_HALT_EXIT, 1);
@@ -82,8 +83,7 @@ bhyve_init_vcpu(struct vcpu *vcpu)
 		 */
 		err = vm_get_capability(vcpu, VM_CAP_PAUSE_EXIT, &tmp);
 		if (err < 0) {
-			fprintf(stderr,
-			    "SMP mux requested, no pause support\n");
+			EPRINTLN("SMP mux requested, no pause support");
 			exit(4);
 		}
 		vm_set_capability(vcpu, VM_CAP_PAUSE_EXIT, 1);
@@ -95,7 +95,7 @@ bhyve_init_vcpu(struct vcpu *vcpu)
 		err = vm_set_x2apic_state(vcpu, X2APIC_DISABLED);
 
 	if (err) {
-		fprintf(stderr, "Unable to set x2apic state (%d)\n", err);
+		EPRINTLN("Unable to set x2apic state (%d)", err);
 		exit(4);
 	}
 
diff --git a/usr.sbin/bhyve/amd64/e820.c b/usr.sbin/bhyve/amd64/e820.c
index 545878aad39f..456ce0330b50 100644
--- a/usr.sbin/bhyve/amd64/e820.c
+++ b/usr.sbin/bhyve/amd64/e820.c
@@ -17,6 +17,7 @@
 #include <stdlib.h>
 #include <string.h>
 
+#include "debug.h"
 #include "e820.h"
 #include "qemu_fwcfg.h"
 
@@ -93,11 +94,11 @@ e820_dump_table(void)
 	struct e820_element *element;
 	uint64_t i;
 
-	fprintf(stderr, "E820 map:\n");
+	EPRINTLN("E820 map:");
 	
 	i = 0;
 	TAILQ_FOREACH(element, &e820_table, chain) {
-		fprintf(stderr, "  (%4lu) [%16lx, %16lx] %s\n", i,
+		EPRINTLN("  (%4lu) [%16lx, %16lx] %s", i,
 		    element->base, element->end,
 		    e820_get_type_name(element->type));
 
diff --git a/usr.sbin/bhyve/amd64/vmexit.c b/usr.sbin/bhyve/amd64/vmexit.c
index 5d903d98f277..2c01c63f6454 100644
--- a/usr.sbin/bhyve/amd64/vmexit.c
+++ b/usr.sbin/bhyve/amd64/vmexit.c
@@ -83,7 +83,7 @@ vmexit_inout(struct vmctx *ctx, struct vcpu *vcpu, struct vm_run *vmrun)
 
 	error = emulate_inout(ctx, vcpu, vme);
 	if (error) {
-		fprintf(stderr, "Unhandled %s%c 0x%04x at 0x%lx\n",
+		EPRINTLN("Unhandled %s%c 0x%04x at 0x%lx",
 		    in ? "in" : "out",
 		    bytes == 1 ? 'b' : (bytes == 2 ? 'w' : 'l'),
 		    port, vme->rip);
@@ -107,7 +107,7 @@ vmexit_rdmsr(struct vmctx *ctx __unused, struct vcpu *vcpu,
 	val = 0;
 	error = emulate_rdmsr(vcpu, vme->u.msr.code, &val);
 	if (error != 0) {
-		fprintf(stderr, "rdmsr to register %#x on vcpu %d\n",
+		EPRINTLN("rdmsr to register %#x on vcpu %d",
 		    vme->u.msr.code, vcpu_id(vcpu));
 		if (get_config_bool("x86.strictmsr")) {
 			vm_inject_gp(vcpu);
@@ -137,7 +137,7 @@ vmexit_wrmsr(struct vmctx *ctx __unused, struct vcpu *vcpu,
 
 	error = emulate_wrmsr(vcpu, vme->u.msr.code, vme->u.msr.wval);
 	if (error != 0) {
-		fprintf(stderr, "wrmsr to register %#x(%#lx) on vcpu %d\n",
+		EPRINTLN("wrmsr to register %#x(%#lx) on vcpu %d",
 		    vme->u.msr.code, vme->u.msr.wval, vcpu_id(vcpu));
 		if (get_config_bool("x86.strictmsr")) {
 			vm_inject_gp(vcpu);
@@ -239,17 +239,17 @@ vmexit_vmx(struct vmctx *ctx, struct vcpu *vcpu, struct vm_run *vmrun)
 
 	vme = vmrun->vm_exit;
 
-	fprintf(stderr, "vm exit[%d]\n", vcpu_id(vcpu));
-	fprintf(stderr, "\treason\t\tVMX\n");
-	fprintf(stderr, "\trip\t\t0x%016lx\n", vme->rip);
-	fprintf(stderr, "\tinst_length\t%d\n", vme->inst_length);
-	fprintf(stderr, "\tstatus\t\t%d\n", vme->u.vmx.status);
-	fprintf(stderr, "\texit_reason\t%u (%s)\n", vme->u.vmx.exit_reason,
+	EPRINTLN("vm exit[%d]", vcpu_id(vcpu));
+	EPRINTLN("\treason\t\tVMX");
+	EPRINTLN("\trip\t\t0x%016lx", vme->rip);
+	EPRINTLN("\tinst_length\t%d", vme->inst_length);
+	EPRINTLN("\tstatus\t\t%d", vme->u.vmx.status);
+	EPRINTLN("\texit_reason\t%u (%s)", vme->u.vmx.exit_reason,
 	    vmexit_vmx_desc(vme->u.vmx.exit_reason));
-	fprintf(stderr, "\tqualification\t0x%016lx\n",
+	EPRINTLN("\tqualification\t0x%016lx",
 	    vme->u.vmx.exit_qualification);
-	fprintf(stderr, "\tinst_type\t\t%d\n", vme->u.vmx.inst_type);
-	fprintf(stderr, "\tinst_error\t\t%d\n", vme->u.vmx.inst_error);
+	EPRINTLN("\tinst_type\t\t%d", vme->u.vmx.inst_type);
+	EPRINTLN("\tinst_error\t\t%d", vme->u.vmx.inst_error);
 #ifdef DEBUG_EPT_MISCONFIG
 	if (vme->u.vmx.exit_reason == EXIT_REASON_EPT_MISCONFIG) {
 		vm_get_register(vcpu,
@@ -257,9 +257,9 @@ vmexit_vmx(struct vmctx *ctx, struct vcpu *vcpu, struct vm_run *vmrun)
 		    &ept_misconfig_gpa);
 		vm_get_gpa_pmap(ctx, ept_misconfig_gpa, ept_misconfig_pte,
 		    &ept_misconfig_ptenum);
-		fprintf(stderr, "\tEPT misconfiguration:\n");
-		fprintf(stderr, "\t\tGPA: %#lx\n", ept_misconfig_gpa);
-		fprintf(stderr, "\t\tPTE(%d): %#lx %#lx %#lx %#lx\n",
+		EPRINTLN("\tEPT misconfiguration:");
+		EPRINTLN("\t\tGPA: %#lx", ept_misconfig_gpa);
+		EPRINTLN("\t\tPTE(%d): %#lx %#lx %#lx %#lx",
 		    ept_misconfig_ptenum, ept_misconfig_pte[0],
 		    ept_misconfig_pte[1], ept_misconfig_pte[2],
 		    ept_misconfig_pte[3]);
@@ -275,13 +275,13 @@ vmexit_svm(struct vmctx *ctx __unused, struct vcpu *vcpu, struct vm_run *vmrun)
 
 	vme = vmrun->vm_exit;
 
-	fprintf(stderr, "vm exit[%d]\n", vcpu_id(vcpu));
-	fprintf(stderr, "\treason\t\tSVM\n");
-	fprintf(stderr, "\trip\t\t0x%016lx\n", vme->rip);
-	fprintf(stderr, "\tinst_length\t%d\n", vme->inst_length);
-	fprintf(stderr, "\texitcode\t%#lx\n", vme->u.svm.exitcode);
-	fprintf(stderr, "\texitinfo1\t%#lx\n", vme->u.svm.exitinfo1);
-	fprintf(stderr, "\texitinfo2\t%#lx\n", vme->u.svm.exitinfo2);
+	EPRINTLN("vm exit[%d]", vcpu_id(vcpu));
+	EPRINTLN("\treason\t\tSVM");
+	EPRINTLN("\trip\t\t0x%016lx", vme->rip);
+	EPRINTLN("\tinst_length\t%d", vme->inst_length);
+	EPRINTLN("\texitcode\t%#lx", vme->u.svm.exitcode);
+	EPRINTLN("\texitinfo1\t%#lx", vme->u.svm.exitinfo1);
+	EPRINTLN("\texitinfo2\t%#lx", vme->u.svm.exitinfo2);
 	return (VMEXIT_ABORT);
 }
 
@@ -413,7 +413,7 @@ vmexit_suspend(struct vmctx *ctx, struct vcpu *vcpu, struct vm_run *vmrun)
 	case VM_SUSPEND_TRIPLEFAULT:
 		exit(3);
 	default:
-		fprintf(stderr, "vmexit_suspend: invalid reason %d\n", how);
+		EPRINTLN("vmexit_suspend: invalid reason %d", how);
 		exit(100);
 	}
 	return (0);	/* NOTREACHED */
diff --git a/usr.sbin/bhyve/bhyverun.c b/usr.sbin/bhyve/bhyverun.c
index 581e45a7492c..b2b7015d1238 100644
--- a/usr.sbin/bhyve/bhyverun.c
+++ b/usr.sbin/bhyve/bhyverun.c
@@ -467,7 +467,7 @@ fbsdrun_deletecpu(int vcpu)
 
 	pthread_mutex_lock(&resetcpu_mtx);
 	if (!CPU_ISSET(vcpu, &cpumask)) {
-		fprintf(stderr, "Attempting to delete unknown cpu %d\n", vcpu);
+		EPRINTLN("Attempting to delete unknown cpu %d", vcpu);
 		exit(4);
 	}
 
@@ -531,7 +531,7 @@ vm_loop(struct vmctx *ctx, struct vcpu *vcpu)
 			exit(4);
 		}
 	}
-	fprintf(stderr, "vm_run error %d, errno %d\n", error, errno);
+	EPRINTLN("vm_run error %d, errno %d", error, errno);
 }
 
 static int
@@ -934,13 +934,13 @@ main(int argc, char *argv[])
 		exit(4);
 
 	if (qemu_fwcfg_init(ctx) != 0) {
-		fprintf(stderr, "qemu fwcfg initialization error");
+		fprintf(stderr, "qemu fwcfg initialization error\n");
 		exit(4);
 	}
 
 	if (qemu_fwcfg_add_file("opt/bhyve/hw.ncpu", sizeof(guest_ncpus),
 	    &guest_ncpus) != 0) {
-		fprintf(stderr, "Could not add qemu fwcfg opt/bhyve/hw.ncpu");
+		fprintf(stderr, "Could not add qemu fwcfg opt/bhyve/hw.ncpu\n");
 		exit(4);
 	}
 
@@ -948,11 +948,12 @@ main(int argc, char *argv[])
 	 * Exit if a device emulation finds an error in its initialization
 	 */
 	if (init_pci(ctx) != 0) {
-		perror("device emulation initialization error");
+		EPRINTLN("Device emulation initialization error: %s",
+		    strerror(errno));
 		exit(4);
 	}
 	if (init_tpm(ctx) != 0) {
-		fprintf(stderr, "Failed to init TPM device");
+		EPRINTLN("Failed to init TPM device");
 		exit(4);
 	}
 
@@ -975,33 +976,33 @@ main(int argc, char *argv[])
 
 #ifdef BHYVE_SNAPSHOT
 	if (restore_file != NULL) {
-		fprintf(stdout, "Pausing pci devs...\r\n");
+		FPRINTLN(stdout, "Pausing pci devs...");
 		if (vm_pause_devices() != 0) {
-			fprintf(stderr, "Failed to pause PCI device state.\n");
+			EPRINTLN("Failed to pause PCI device state.");
 			exit(1);
 		}
 
-		fprintf(stdout, "Restoring vm mem...\r\n");
+		FPRINTLN(stdout, "Restoring vm mem...");
 		if (restore_vm_mem(ctx, &rstate) != 0) {
-			fprintf(stderr, "Failed to restore VM memory.\n");
+			EPRINTLN("Failed to restore VM memory.");
 			exit(1);
 		}
 
-		fprintf(stdout, "Restoring pci devs...\r\n");
+		FPRINTLN(stdout, "Restoring pci devs...");
 		if (vm_restore_devices(&rstate) != 0) {
-			fprintf(stderr, "Failed to restore PCI device state.\n");
+			EPRINTLN("Failed to restore PCI device state.");
 			exit(1);
 		}
 
-		fprintf(stdout, "Restoring kernel structs...\r\n");
+		FPRINTLN(stdout, "Restoring kernel structs...");
 		if (vm_restore_kern_structs(ctx, &rstate) != 0) {
-			fprintf(stderr, "Failed to restore kernel structs.\n");
+			EPRINTLN("Failed to restore kernel structs.");
 			exit(1);
 		}
 
-		fprintf(stdout, "Resuming pci devs...\r\n");
+		FPRINTLN(stdout, "Resuming pci devs...");
 		if (vm_resume_devices() != 0) {
-			fprintf(stderr, "Failed to resume PCI device state.\n");
+			EPRINTLN("Failed to resume PCI device state.");
 			exit(1);
 		}
 	}
diff --git a/usr.sbin/bhyve/block_if.c b/usr.sbin/bhyve/block_if.c
index 93ddf6d8e0c6..29b8910101f6 100644
--- a/usr.sbin/bhyve/block_if.c
+++ b/usr.sbin/bhyve/block_if.c
@@ -1025,7 +1025,7 @@ blockif_pause(struct blockif_ctxt *bc)
 	pthread_mutex_unlock(&bc->bc_mtx);
 
 	if (!bc->bc_rdonly && blockif_flush_bc(bc))
-		fprintf(stderr, "%s: [WARN] failed to flush backing file.\r\n",
+		EPRINTLN("%s: [WARN] failed to flush backing file.",
 			__func__);
 }
 
diff --git a/usr.sbin/bhyve/bootrom.c b/usr.sbin/bhyve/bootrom.c
index cf527b98af89..64f1921f901e 100644
--- a/usr.sbin/bhyve/bootrom.c
+++ b/usr.sbin/bhyve/bootrom.c
@@ -237,14 +237,14 @@ bootrom_loadrom(struct vmctx *ctx, const nvlist_t *nvl)
 	if (varfile != NULL) {
 		varfd = open(varfile, O_RDWR);
 		if (varfd < 0) {
-			fprintf(stderr, "Error opening bootrom variable file "
-			    "\"%s\": %s\n", varfile, strerror(errno));
+			EPRINTLN("Error opening bootrom variable file "
+			    "\"%s\": %s", varfile, strerror(errno));
 			goto done;
 		}
 
 		if (fstat(varfd, &sbuf) < 0) {
-			fprintf(stderr,
-			    "Could not fstat bootrom variable file \"%s\": %s\n",
+			EPRINTLN(
+			    "Could not fstat bootrom variable file \"%s\": %s",
 			    varfile, strerror(errno));
 			goto done;
 		}
@@ -254,7 +254,7 @@ bootrom_loadrom(struct vmctx *ctx, const nvlist_t *nvl)
 
 	if (var_size > BOOTROM_SIZE ||
 	    (var_size != 0 && var_size < PAGE_SIZE)) {
-		fprintf(stderr, "Invalid bootrom variable size %ld\n",
+		EPRINTLN("Invalid bootrom variable size %ld",
 		    var_size);
 		goto done;
 	}
@@ -262,8 +262,8 @@ bootrom_loadrom(struct vmctx *ctx, const nvlist_t *nvl)
 	total_size = rom_size + var_size;
 
 	if (total_size > BOOTROM_SIZE) {
-		fprintf(stderr, "Invalid bootrom and variable aggregate size "
-		    "%ld\n", total_size);
+		EPRINTLN("Invalid bootrom and variable aggregate size %ld",
+		    total_size);
 		goto done;
 	}
 
diff --git a/usr.sbin/bhyve/gdb.c b/usr.sbin/bhyve/gdb.c
index dcd733c484ca..55178677f837 100644
--- a/usr.sbin/bhyve/gdb.c
+++ b/usr.sbin/bhyve/gdb.c
@@ -59,6 +59,7 @@
 
 #include "bhyverun.h"
 #include "config.h"
+#include "debug.h"
 #include "gdb.h"
 #include "mem.h"
 #include "mevent.h"
@@ -890,7 +891,7 @@ gdb_cpu_breakpoint(struct vcpu *vcpu, struct vm_exit *vmexit)
 	int error, vcpuid;
 
 	if (!gdb_active) {
-		fprintf(stderr, "vm_loop: unexpected VMEXIT_DEBUG\n");
+		EPRINTLN("vm_loop: unexpected VMEXIT_DEBUG");
 		exit(4);
 	}
 	vcpuid = vcpu_id(vcpu);
diff --git a/usr.sbin/bhyve/pci_ahci.c b/usr.sbin/bhyve/pci_ahci.c
index b69c099225db..1eef285a871c 100644
--- a/usr.sbin/bhyve/pci_ahci.c
+++ b/usr.sbin/bhyve/pci_ahci.c
@@ -2610,7 +2610,7 @@ pci_ahci_snapshot(struct vm_snapshot_meta *meta)
 		/* Mostly for restore; save is ensured by the lines above. */
 		if (((bctx == NULL) && (port->bctx != NULL)) ||
 		    ((bctx != NULL) && (port->bctx == NULL))) {
-			fprintf(stderr, "%s: ports not matching\r\n", __func__);
+			EPRINTLN("%s: ports not matching", __func__);
 			ret = EINVAL;
 			goto done;
 		}
@@ -2619,9 +2619,8 @@ pci_ahci_snapshot(struct vm_snapshot_meta *meta)
 			continue;
 
 		if (port->port != i) {
-			fprintf(stderr, "%s: ports not matching: "
-					"actual: %d expected: %d\r\n",
-					__func__, port->port, i);
+			EPRINTLN("%s: ports not matching: "
+			    "actual: %d expected: %d", __func__, port->port, i);
 			ret = EINVAL;
 			goto done;
 		}
diff --git a/usr.sbin/bhyve/pci_xhci.c b/usr.sbin/bhyve/pci_xhci.c
index 2d37cb0f08fc..99c1d20b3378 100644
--- a/usr.sbin/bhyve/pci_xhci.c
+++ b/usr.sbin/bhyve/pci_xhci.c
@@ -3102,8 +3102,8 @@ pci_xhci_snapshot(struct vm_snapshot_meta *meta)
 
 		/* check if the restored device (when restoring) is sane */
 		if (restore_idx != i) {
-			fprintf(stderr, "%s: idx not matching: actual: %d, "
-				"expected: %d\r\n", __func__, restore_idx, i);
+			EPRINTLN("%s: idx not matching: actual: %d, "
+			    "expected: %d", __func__, restore_idx, i);
 			ret = EINVAL;
 			goto done;
 		}
@@ -3118,9 +3118,9 @@ pci_xhci_snapshot(struct vm_snapshot_meta *meta)
 		if (meta->op == VM_SNAPSHOT_RESTORE) {
 			dname[sizeof(dname) - 1] = '\0';
 			if (strcmp(dev->dev_ue->ue_emu, dname)) {
-				fprintf(stderr, "%s: device names mismatch: "
-					"actual: %s, expected: %s\r\n",
-					__func__, dname, dev->dev_ue->ue_emu);
+				EPRINTLN("%s: device names mismatch: "
+				    "actual: %s, expected: %s",
+				    __func__, dname, dev->dev_ue->ue_emu);
 
 				ret = EINVAL;
 				goto done;
diff --git a/usr.sbin/bhyve/snapshot.c b/usr.sbin/bhyve/snapshot.c
index 5f2b5e1fafe4..edce55c03eae 100644
--- a/usr.sbin/bhyve/snapshot.c
+++ b/usr.sbin/bhyve/snapshot.c
@@ -156,13 +156,13 @@ strcat_extension(const char *base_str, const char *ext)
 	ext_len = strnlen(ext, NAME_MAX);
 
 	if (base_len + ext_len > NAME_MAX) {
-		fprintf(stderr, "Filename exceeds maximum length.\n");
+		EPRINTLN("Filename exceeds maximum length.");
 		return (NULL);
 	}
 
 	res = malloc(base_len + ext_len + 1);
 	if (res == NULL) {
-		perror("Failed to allocate memory.");
+		EPRINTLN("Failed to allocate memory: %s", strerror(errno));
 		return (NULL);
 	}
 
@@ -177,7 +177,7 @@ void
 destroy_restore_state(struct restore_state *rstate)
 {
 	if (rstate == NULL) {
-		fprintf(stderr, "Attempting to destroy NULL restore struct.\n");
+		EPRINTLN("Attempting to destroy NULL restore struct.");
 		return;
 	}
 
diff --git a/usr.sbin/bhyve/snapshot.h b/usr.sbin/bhyve/snapshot.h
index b60773cb99c0..8bebdafd6117 100644
--- a/usr.sbin/bhyve/snapshot.h
+++ b/usr.sbin/bhyve/snapshot.h
@@ -118,8 +118,7 @@ do {										\
 	    (RNULL), (META));							\
 	if ((RES) != 0) {							\
 		if ((RES) == EFAULT)						\
-			fprintf(stderr, "%s: invalid address: %s\r\n",		\
-				__func__, #ADDR);				\
+			EPRINTLN("%s: invalid address: %s", __func__, #ADDR);	\
 		goto LABEL;							\
 	}									\
 } while (0)